Buy or Renew
Buy or Renew
Cisco + Splunk: It’s a new day for your data. Learn more.
 
cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results for 
Search instead for 
Did you mean: 
cancel
Start a conversation
2704
Views
0
Helpful
5
Replies

Troubleshooting Inbound Call Issues

mumbles202
Level 5
Level 5

‎11-20-2017 08:59 AM - edited ‎03-17-2019 11:38 AM

Working on an older CUCM (BE5K running 7.1.3) which has 2 H.323 gateways configured.  The second gateway has 4 POTS lines connected to a 4 port FXO with this basic configuration:

 

voice-port 0/0/0

 description Line 1

 connection plar 1000

 

voice-port 0/0/1

 description Line 4

 connection plar 1003

 

voice-port 0/0/2

 description Line 2

 connection plar 1001

 

voice-port 0/0/3

 description Line 3

 connection plar 1002

 

dial-peer voice 1000 voip

description DIAL PEER FOR VOIP CALL TO CCM
preference 1
destination-pattern 100.
progress_ind setup enable 3
voice-class codec 1
voice-class h323 1
session target ipv4:10.0.40.10
dtmf-relay h245-alphanumeric

 

The 4 lines are part of a hunt group from the carrier that rings and circles back to line 1 if line 4 is busy. This has been in production for some time and working normally, with the only somewhat recent change being the carrier adding line 4 to the hunt and enabling the circular nature. 

 

All the extensions are the primary dn on the their end users phones, with 1001-1003 also appearing on 2 7914 addon modules that some assistants maintain.  What's been happening recently is a call comes in on Line 3 (debugs on the gateway indicate that the call is ringing in on 0/0/3), but as soon as the call is answered by extension 1003 the call "jumps" to 1002.  The user at 1002 then has to park the call or transfer it back to 1003.  From what I've been told, this seems to occur depending on the calling party, where if it happens once to CallerA it will happen on subsequent calls from that caller, but if CallerB (myself for example) calls in the call completes normally.  I'm trying to get more information and pull the CUCM logs this afternoon. 

Labels:
0 Helpful
5 Replies 5

Jonathan Unger
Level 7
Level 7

‎11-20-2017 08:24 PM

Hi There,

 

It would be helpful if you can pull the CM logs. If you are able to post the logs please include the following information:

  1. Called party
  2. Calling party
  3. Date/Time
  4. Short summary of the call behaviour.

Thanks!

0 Helpful

mumbles202
Level 5
Level 5
In response to Jonathan Unger

‎11-22-2017 11:10 AM

Attached is a log that should have the call in it.  Call details are below:

 

Call Time: 12:17 pm
Calling Number: 9731112222
Called Number: Line 3, 3024
Behavior: Call came in(incoming on Line 3), rang on 3024. As soon as the call was answered on 3024 it jumped to 3065. 3065 then had to transfer the call back to 3024.

Preview file
793 KB
0 Helpful

Jonathan Unger
Level 7
Level 7
In response to mumbles202

‎11-22-2017 10:07 PM - edited ‎11-22-2017 10:08 PM

Here is a breakdown of what I see with the trace file (trace snippets in blue).

 

  1. The first call I see come in from the VGW destined for 3024 does not have any CLID information associated with it (no reference to 9731112222).
    11/17/2017 12:17:07.836 CCM|SPROCRas - {
    ...

  2. CUCM does a lookup for called number 3024
    11/17/2017 12:17:07.840 CCM||PretransformCallingPartyNumber=
    |CallingPartyNumber=
    |DialingPartition=PT_Internal
    |DialingPattern=3024
    ...

  3. CUCM starts to dispatch the call to 3 devices (I assume there is a shared line for 3024):
    11/17/2017 12:17:07.842 CCM|LineCdpc(168262): -dispatchToAllDevices-, sigName=CcSetupReq, device=SEP000F11117700|<CLID::StandAloneCluster><NID::10.0.40.10><CT::0,0,0,0.0><IP::10.1.0.20><DEV::><LVL::Detailed><MASK::0800>
    11/17/2017 12:17:07.842 CCM|LineCdpc(168262): -dispatchToAllDevices-, sigName=CcSetupReq, device=SEP001A1111F691|<CLID::StandAloneCluster><NID::10.0.40.10><CT::0,0,0,0.0><IP::10.1.0.20><DEV::><LVL::Detailed><MASK::0800>
    11/17/2017 12:17:07.842 CCM|LineCdpc(168262): -dispatchToAllDevices-, sigName=CcSetupReq, device=SEP001A11110377|<CLID::StandAloneCluster><NID::10.0.40.10><CT::0,0,0,0.0><IP::10.1.0.20><DEV::><LVL::Detailed><MASK::0800>

  4. CUCM instructs the 3 phones to ring, text identified in red is the TCP handle of the connection between CUCM and each individual phone. Any message between CUCM and a phone will be identified with this handle.
    11/17/2017 12:17:07.845 CCM|StationD:    (0000906) SetRinger ringMode=3(OutsideRing).|<CLID::StandAloneCluster><NID::10.0.40.10><CT::0,0,0,0.0><IP::10.1.0.20><DEV::><LVL::State Transition><MASK::0020>
    ...
    11/17/2017 12:17:07.846 CCM|StationD:    (0000964) SetRinger ringMode=3(OutsideRing).|<CLID::StandAloneCluster><NID::10.0.40.10><CT::0,0,0,0.0><IP::10.1.0.20><DEV::><LVL::State Transition><MASK::0020>
    ...
    11/17/2017 12:17:07.847 CCM|StationD:    (0000967) SetRinger ringMode=3(OutsideRing).|<CLID::StandAloneCluster><NID::10.0.40.10><CT::0,0,0,0.0><IP::10.1.0.20><DEV::><LVL::State Transition><MASK::0020>

  5. One of the phones with handle 0000964 goes offhook (7 seconds later) to pick up the call:
    11/17/2017 12:17:13.206 CCM|StationInit: (0000964) OffHook.|<CLID::StandAloneCluster><NID::10.0.40.10><CT::1,100,39,1.105744254><IP::10.1.0.66><DEV::SEP001A1111F691><LVL::State Transition><MASK::0020>

  6. Media negotiation takes place and the phone is instructed to send/receive media:
    11/17/2017 12:17:13.426 CCM|StationD:    (0000964) startMediaTransmission conferenceID=17858076 passThruPartyID=16924178 remoteIpAddress=IpAddr.type:0 ipAddr:0x0a010014000000000000000000000000(10.1.0.20) remotePortNumber=18588 milliSecondPacketSize=20 compressType=4(Media_Payload_G711Ulaw64k) RFC2833PayloadType=0 qualifierOut=?. myIP: IpAddr.type:0 ipv4Addr:0x0a010042(10.1.0.66) |<CLID::StandAloneCluster><NID::10.0.40.10><CT::1,100,16,70290.7><IP::10.0.40.10><DEV::Port 44870><LVL::Significant><MASK::0020>

    11/17/2017 12:17:13.484 CCM|StationInit: (0000964) OpenReceiveChannelAck Status=0, IpAddr=IpAddr.type:0 ipAddr:0x0a010042000000000000000000000000(10.1.0.66), Port=26018, PartyID=16924178|<CLID::StandAloneCluster><NID::10.0.40.10><CT::1,100,39,1.105744255><IP::10.1.0.66><DEV::SEP001A1111F691><LVL::State Transition><MASK::0020>

  7. The user hangs up the call (approx 9 seconds after the call was set up), subsequently media is torn down and the call is cleared for the 2 call legs 17858075 and 17858076:
    11/17/2017 12:17:22.198 CCM|StationInit: (0000964) OnHook.|<CLID::StandAloneCluster><NID::10.0.40.10><CT::1,100,39,1.105744307><IP::10.1.0.66><DEV::SEP001A1111F691><LVL::State Transition><MASK::0020>

    11/17/2017 12:17:22.203 CCM|ConnectionManager - wait_AuDisconnectRequest(17858075,17858076),disconnectType(1), IFHandling(0,0)|<CLID::StandAloneCluster><NID::10.0.40.10><CT::1,100,39,1.105744307><IP::10.1.0.66><DEV::SEP001A1111F691><LVL::Arbitrary><MASK::0800>

    11/17/2017 12:17:22.276 CCM|ConnectionManager - deleteMediaInfoEntry(17858075): ENTRY DELETED, size=11|<CLID::StandAloneCluster><NID::10.0.40.10><CT::1,100,16,70290.9><IP::10.0.40.10><DEV::Port 44870><LVL::Arbitrary><MASK::0800>

    11/17/2017 12:17:22.276 CCM|ConnectionManager - deleteMediaInfoEntry(17858076): ENTRY DELETED, size=10|<CLID::StandAloneCluster><NID::10.0.40.10><CT::1,100,16,70290.9><IP::10.0.40.10><DEV::Port 44870><LVL::Arbitrary><MASK::0800>

In summary:

  • Based on the description of the call you provided (call initially goes to 3024) it looks like the user picked up the call and then hung up normally after approximately 9 seconds. I did not see the call jump to another extension as soon as the 3024 user picked up the call.
  • I did see a new call come in at 12:17:17 from 10.0.40.20 destined for 3065. But the calling number was not ending in 2222, it ended in 7200.

 

A few follow up questions:

  1. Where is the translation from your PLAR of 1XXX to 3XXX taking place, how does 1002 get translated to 3024?
  2. Can you confirm that 10.0.40.20 is the VGW which the call should be coming in from (that is where I see the initial H.225 setup message for the first call destined for 3024).
  3. What is device 10.1.0.20? Should it be involved with this call flow?
  4. Are you 100% sure that you provided the correct traces for the failed call? If possible please provide the approximate second that the call started, there are 6000+ lines of log and several calls that took place during the 12:17 minute.

0 Helpful

mumbles202
Level 5
Level 5
In response to Jonathan Unger

‎11-27-2017 01:00 PM

Thanks for the response.  I posted a generic configuration, the actual voice-ports are configured like this:  

 

voice-port 0/0/0
trunk-group POTS 1
connection plar 3075
description Line 1
caller-id enable
!
voice-port 0/0/1
trunk-group POTS 1
connection plar 3082
description Line 4
caller-id enable
!
voice-port 0/0/2
trunk-group POTS 1
connection plar 3065
description Line 2
caller-id enable
!
voice-port 0/0/3
trunk-group POTS 1
connection plar 3024
description Line 3
caller-id enable

 

10.1.0.20 is the gateway where the inbound calls come in.  10.0.40.20 is the gateway at the main location that has a PRI (outgoing calls use this gateway and inbound calls for HQ come in here). 

 

I'll try to get the logs from the gateway and get a more exact time. 

0 Helpful

mumbles202
Level 5
Level 5
In response to mumbles202

‎11-29-2017 08:30 AM

Had another call issue this morning, pulled the logs and think I might be putting together what is happening. 

 

So if we go with these numbers:

Line 1 - 1112221231 - should ring 1001

Line 2 - 1112221232- should ring 1002

Line 3 - 1112221233- should ring 1003

Line 4 - 1112221234- should ring 1004

 

Ext 1 - 1001

Ext 2 - 1002

Ext 3 - 1003

Ext 4 - 1004

 

 

Initial call comes in on 1112221233, is answered based on the logs I see in CUCM, but there isn't any audio.  The call then "jumps" to a different extension. 

 

 

Looking through the logs I see a 2nd call for 1002  that has a redirected number of 1112221233 hitting the gateway in HQ. 

 

I called the carrier and they advised that 1112221233 has a CFNA setup on the carrier end that points to the DID for that user on the HQ PRI, 1112221002.  That gateway is configured in CUCM to only use the last 4 digits as significant for inbound calls.  I'm thinking the carrier never gets the signaling that the call was connected, then follows the CFNA and sends the call to the PRI.  VG in HQ sends call to CUCM, CUCM truncates to 1002 and does lookup and since that matches Ext 2 it correctly sends the call to that phone.   To the end user it appears the call jumps because of the time frame.

 

Plausible?

0 Helpful
Customers Also Viewed These Support Documents