cancel
Showing results for 
Search instead for 
Did you mean: 
cancel
6034
Views
25
Helpful
5
Replies

delay in audio after picking up call from agent desktop

Tom Ribbens
Level 1
Level 1

We are running a CUCM9 cluster with Contact Center Express 9. When callers dial in, they end up in a CSQ after a couple of menu's. Then, when the agent picks up the phone, it takes about 1-2 seconds (long enough to miss the complete welcome greeting) before audio is established. This does not happen when the user is called on their phones directly.

I took a Wireshark trace, and did see that the RTP packets indeed only start flowing when voice is established, so too late.

I'm at a loss at how to troubleshoot this though.

1 Accepted Solution

Accepted Solutions

Here is where the agent answers the call:

77977763.001 |15:16:18.757 |AppInfo  |StationInit: (0117045) StationMediaPathEvt Handset (2) = On (1)

 

 

CUCM then goes through the inactive media exchange as expected on the SIP leg:

77977946.001 |15:16:18.792 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989381,NET]
INVITE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f4a13e994
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Supported: timer,resource-priority,replaces
Min-SE:  1800
Cisco-Guid: 1090515800-3470201315-2443690124-1625683936
User-Agent: Cisco-CUCM9.1
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 103 INVITE
Max-Forwards: 70
Expires: 180
Allow-Events: presence
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires:  1800;refresher=uac
P-Asserted-Identity: <sip:20020053@172.25.63.122>
Remote-Party-ID: <sip:20020053@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Type: application/sdp
Content-Length: 189

v=0
o=CiscoSystemsCCM-SIP 593852 4 IN IP4 172.25.63.122
s=SIP Call
c=IN IP4 0.0.0.0
t=0 0
m=audio 4000 RTP/AVP 18
a=X-cisco-media:umoh
a=rtpmap:18 G729/8000
a=ptime:20
a=inactive

 

77977954.001 |15:16:18.828 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 1044 from 172.25.40.165:[63621]:
[1989383,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f4a13e994
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
CSeq: 103 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: <sip:+32498611742@172.25.40.165>;party=called;screen=yes;privacy=off
Contact: <sip:20020053@172.25.40.165:5060>
Supported: replaces
Supported: sdp-anat
Server: Cisco-SIPGateway/IOS-15.2.4.M4
Require: timer
Session-Expires:  1800;refresher=uac
Supported: timer
Content-Type: application/sdp
Content-Length: 229

v=0
o=CiscoSystemsSIP-GW-UserAgent 9504 365 IN IP4 172.25.40.165
s=SIP Call
c=IN IP4 172.25.40.165
t=0 0
m=audio 24904 RTP/AVP 18
c=IN IP4 172.25.40.165
a=inactive
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=ptime:20

 

After this, the transfer is then completed to the agent and an Update is sent on the SIP leg:

77978200.001 |15:16:18.858 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989385,NET]
UPDATE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f624c53fcd
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
User-Agent: Cisco-CUCM9.1
Max-Forwards: 70
Supported: timer,resource-priority,replaces
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 104 UPDATE
Supported: X-cisco-srtp-fallback
Supported: Geolocation
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

CUCM doesn't get a response from the CUBE right away so sends another Update:

77978243.001 |15:16:19.376 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989386,NET]
UPDATE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f624c53fcd
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
User-Agent: Cisco-CUCM9.1
Max-Forwards: 70
Supported: timer,resource-priority,replaces
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 104 UPDATE
Supported: X-cisco-srtp-fallback
Supported: Geolocation
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

CUBE responds with a 491 Request Pending message since it is still working on the first Update:

77978253.001 |15:16:19.630 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 344 from 172.25.40.165:[63621]:
[1989387,NET]
SIP/2.0 491 Request Pending
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f624c53fcd
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
CSeq: 104 UPDATE
Content-Length: 0

 

We finally get a 200 OK in response to the Update:

77978257.001 |15:16:19.631 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 501 from 172.25.40.165:[63621]:
[1989388,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f624c53fcd
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:19 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Server: Cisco-SIPGateway/IOS-15.2.4.M4
CSeq: 104 UPDATE
Allow-Events: telephone-event
Contact: <sip:20020053@172.25.40.165:5060>
Supported: timer
Content-Length: 0

 

CUCM ignores this as a duplicate response though:

77978258.006 |15:16:19.631 |AppInfo  |//SIP/Stack/Info/0x118830d0/sact_active_new_message_response: Duplicate/unexpected UPDATE response ignored

 

 

It then sends another Update out:

77978261.001 |15:16:19.844 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989389,NET]
UPDATE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f742ad3b70
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
User-Agent: Cisco-CUCM9.1
Max-Forwards: 70
Supported: timer,resource-priority,replaces
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 105 UPDATE
Supported: X-cisco-srtp-fallback
Supported: Geolocation
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

Update timer of 1 second (1000ms) expires again with no response so CUCM sends the new Update again:

77978271.001 |15:16:20.348 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989390,NET]
UPDATE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f742ad3b70
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
User-Agent: Cisco-CUCM9.1
Max-Forwards: 70
Supported: timer,resource-priority,replaces
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 105 UPDATE
Supported: X-cisco-srtp-fallback
Supported: Geolocation
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

After that, we get 2 200 OK's for the Update's in a row from the CUBE:

77978277.001 |15:16:20.502 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 497 from 172.25.40.165:[63621]:
[1989391,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f742ad3b70
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:20 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Server: Cisco-SIPGateway/IOS-15.2.4.M4
CSeq: 105 UPDATE
Allow-Events: telephone-event
Contact: <sip:1151@172.25.40.165:5060>
Supported: timer
Content-Length: 0

 

77978280.001 |15:16:20.502 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 497 from 172.25.40.165:[63621]:
[1989392,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f742ad3b70
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:20 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Server: Cisco-SIPGateway/IOS-15.2.4.M4
CSeq: 105 UPDATE
Allow-Events: telephone-event
Contact: <sip:1151@172.25.40.165:5060>
Supported: timer
Content-Length: 0

 

At this point, CUCM is now satisfied and sends out an Invite to establish audio with the agent:

77978290.001 |15:16:20.506 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989393,NET]
INVITE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f818164780
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:20 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Supported: timer,resource-priority,replaces
Min-SE:  1800
Cisco-Guid: 1090515800-3470201315-2443690124-1625683936
User-Agent: Cisco-CUCM9.1
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 106 INVITE
Max-Forwards: 70
Expires: 180
Allow-Events: presence
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires:  1800;refresher=uac
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

CUCM doesn't get a 100 Trying from CUBE before 500ms timer expires:

77978308.001 |15:16:21.012 |AppInfo  |//SIP/SIPHandler/ccbId=0/scbId=0/wait_SIPTimer: TimerExpired type=SIP_TIMER_TRYING value=500 retries=6

 

 

This results in CUCM re-sending the Re-Invite:

77978310.001 |15:16:21.013 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989396,NET]
INVITE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f818164780
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:21 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Supported: timer,resource-priority,replaces
Min-SE:  1800
Cisco-Guid: 1090515800-3470201315-2443690124-1625683936
User-Agent: Cisco-CUCM9.1
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 106 INVITE
Max-Forwards: 70
Expires: 180
Allow-Events: presence
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires:  1800;refresher=uac
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

Now we get the 100 Trying from CUBE:

77978316.001 |15:16:21.307 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 443 from 172.25.40.165:[63621]:
[1989397,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f818164780
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:21 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
CSeq: 106 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-15.2.4.M4
Content-Length: 0

 

Then we get the 200OK from CUBE:

77978322.001 |15:16:21.309 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 1194 from 172.25.40.165:[63621]:
[1989398,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f818164780
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:21 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
CSeq: 106 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: <sip:+32498611742@172.25.40.165>;party=called;screen=yes;privacy=off
Contact: <sip:1151@172.25.40.165:5060>
Supported: replaces
Supported: sdp-anat
Server: Cisco-SIPGateway/IOS-15.2.4.M4
Require: timer
Session-Expires:  1800;refresher=uac
Supported: timer
Content-Type: application/sdp
Content-Length: 382

v=0
o=CiscoSystemsSIP-GW-UserAgent 9504 366 IN IP4 172.25.40.165
s=SIP Call
c=IN IP4 172.25.40.165
t=0 0
m=audio 24904 RTP/AVP 8 18 0 100 101 19
c=IN IP4 172.25.40.165
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:0 PCMU/8000
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:19 CN/8000

 

Agent phone told to start transmitting media:

77978349.001 |15:16:21.313 |AppInfo  |StationD:    (0117045) startMediaTransmission conferenceID=26075143 passThruPartyID=16903885 remoteIpAddress=IpAddr.type:0 ipAddr:0xac1928a5000000000000000000000000(172.25.40.165) remotePortNumber=24904 milliSecondPacketSize=20 compressType=4(Media_Payload_G711Ulaw64k) RFC2833PayloadType=101 qualifierOut=?. myIP: IpAddr.type:0 ipv4Addr:0xac1928b4(172.25.40.180) 

 

 

OpenReceiveChannelAck from the agent's phone gives the SIP side info on where to send it's RTP stream:

77978367.001 |15:16:21.384 |AppInfo  |StationInit: (0117045) OpenReceiveChannelAck Status=0, IpAddr=IpAddr.type:0 ipAddr:0xac1928b4000000000000000000000000(172.25.40.180), Port=30252, PartyID=16903885

 

 

77978398.001 |15:16:21.390 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989402,NET]
ACK sip:1151@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2fa53810a7a
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:21 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Max-Forwards: 70
CSeq: 106 ACK
Allow-Events: presence, kpml
Content-Type: application/sdp
Content-Length: 239

v=0
o=CiscoSystemsCCM-SIP 593852 5 IN IP4 172.25.63.122
s=SIP Call
c=IN IP4 172.25.40.180
b=TIAS:64000
b=AS:64
t=0 0
m=audio 30252 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

 

We now have 2-way audio with the agent about 3 seconds after they answered the call.

 

The cause is that the CUBE is slow to respond to the Update messages for some reason.  There may be high CPU on the CUBE that is causing this.  The timer of 1000ms isn't enough resulting in the Updates being sent out again causing even more delay.

 

I would grab a "debug ccsip messages" on the CUBE for one of these calls to see what the cause of delay is.  Check the CPU/memory usage on the CUBE as well.

 

As a workaround, you could remove UPDATE from the Allow header on CUBE which will get rid of CUCM sending the Updates in the first place:

 

voice class sip-profiles 1 
request REINVITE sip-header Allow-Header modify "UPDATE, " " " 
request INVITE sip-header Allow-Header modify " UPDATE, " " " 
response 180 sip-header Allow-Header modify " UPDATE, " " " 
response 200 sip-header Allow-Header modify " UPDATE, " " " 

 

You can then apply that globally or just on your outbound dial-peers to CUCM.

 

Here's how to apply it globally:

voice service voip 

 sip

  sip-profiles 1

View solution in original post

5 Replies 5

Brian Meade
Level 7
Level 7

Can you grab the CallManager traces for one of these delayed calls and attach them?

 

That will allow us to see what is causing the delay in setting up the audio.

Attached the SDL trace. Calling number is +32498611742.

172.25.63.122 = CUCM 

172.25.63.123 = UCCX

172.25.40.165 = Relevant voice gateway

172.25.40.180 = Phone

Here is where the agent answers the call:

77977763.001 |15:16:18.757 |AppInfo  |StationInit: (0117045) StationMediaPathEvt Handset (2) = On (1)

 

 

CUCM then goes through the inactive media exchange as expected on the SIP leg:

77977946.001 |15:16:18.792 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989381,NET]
INVITE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f4a13e994
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Supported: timer,resource-priority,replaces
Min-SE:  1800
Cisco-Guid: 1090515800-3470201315-2443690124-1625683936
User-Agent: Cisco-CUCM9.1
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 103 INVITE
Max-Forwards: 70
Expires: 180
Allow-Events: presence
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires:  1800;refresher=uac
P-Asserted-Identity: <sip:20020053@172.25.63.122>
Remote-Party-ID: <sip:20020053@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Type: application/sdp
Content-Length: 189

v=0
o=CiscoSystemsCCM-SIP 593852 4 IN IP4 172.25.63.122
s=SIP Call
c=IN IP4 0.0.0.0
t=0 0
m=audio 4000 RTP/AVP 18
a=X-cisco-media:umoh
a=rtpmap:18 G729/8000
a=ptime:20
a=inactive

 

77977954.001 |15:16:18.828 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 1044 from 172.25.40.165:[63621]:
[1989383,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f4a13e994
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
CSeq: 103 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: <sip:+32498611742@172.25.40.165>;party=called;screen=yes;privacy=off
Contact: <sip:20020053@172.25.40.165:5060>
Supported: replaces
Supported: sdp-anat
Server: Cisco-SIPGateway/IOS-15.2.4.M4
Require: timer
Session-Expires:  1800;refresher=uac
Supported: timer
Content-Type: application/sdp
Content-Length: 229

v=0
o=CiscoSystemsSIP-GW-UserAgent 9504 365 IN IP4 172.25.40.165
s=SIP Call
c=IN IP4 172.25.40.165
t=0 0
m=audio 24904 RTP/AVP 18
c=IN IP4 172.25.40.165
a=inactive
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=ptime:20

 

After this, the transfer is then completed to the agent and an Update is sent on the SIP leg:

77978200.001 |15:16:18.858 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989385,NET]
UPDATE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f624c53fcd
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
User-Agent: Cisco-CUCM9.1
Max-Forwards: 70
Supported: timer,resource-priority,replaces
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 104 UPDATE
Supported: X-cisco-srtp-fallback
Supported: Geolocation
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

CUCM doesn't get a response from the CUBE right away so sends another Update:

77978243.001 |15:16:19.376 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989386,NET]
UPDATE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f624c53fcd
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
User-Agent: Cisco-CUCM9.1
Max-Forwards: 70
Supported: timer,resource-priority,replaces
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 104 UPDATE
Supported: X-cisco-srtp-fallback
Supported: Geolocation
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

CUBE responds with a 491 Request Pending message since it is still working on the first Update:

77978253.001 |15:16:19.630 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 344 from 172.25.40.165:[63621]:
[1989387,NET]
SIP/2.0 491 Request Pending
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f624c53fcd
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
CSeq: 104 UPDATE
Content-Length: 0

 

We finally get a 200 OK in response to the Update:

77978257.001 |15:16:19.631 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 501 from 172.25.40.165:[63621]:
[1989388,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f624c53fcd
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:19 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Server: Cisco-SIPGateway/IOS-15.2.4.M4
CSeq: 104 UPDATE
Allow-Events: telephone-event
Contact: <sip:20020053@172.25.40.165:5060>
Supported: timer
Content-Length: 0

 

CUCM ignores this as a duplicate response though:

77978258.006 |15:16:19.631 |AppInfo  |//SIP/Stack/Info/0x118830d0/sact_active_new_message_response: Duplicate/unexpected UPDATE response ignored

 

 

It then sends another Update out:

77978261.001 |15:16:19.844 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989389,NET]
UPDATE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f742ad3b70
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
User-Agent: Cisco-CUCM9.1
Max-Forwards: 70
Supported: timer,resource-priority,replaces
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 105 UPDATE
Supported: X-cisco-srtp-fallback
Supported: Geolocation
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

Update timer of 1 second (1000ms) expires again with no response so CUCM sends the new Update again:

77978271.001 |15:16:20.348 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989390,NET]
UPDATE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f742ad3b70
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:18 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
User-Agent: Cisco-CUCM9.1
Max-Forwards: 70
Supported: timer,resource-priority,replaces
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 105 UPDATE
Supported: X-cisco-srtp-fallback
Supported: Geolocation
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

After that, we get 2 200 OK's for the Update's in a row from the CUBE:

77978277.001 |15:16:20.502 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 497 from 172.25.40.165:[63621]:
[1989391,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f742ad3b70
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:20 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Server: Cisco-SIPGateway/IOS-15.2.4.M4
CSeq: 105 UPDATE
Allow-Events: telephone-event
Contact: <sip:1151@172.25.40.165:5060>
Supported: timer
Content-Length: 0

 

77978280.001 |15:16:20.502 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 497 from 172.25.40.165:[63621]:
[1989392,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f742ad3b70
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:20 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Server: Cisco-SIPGateway/IOS-15.2.4.M4
CSeq: 105 UPDATE
Allow-Events: telephone-event
Contact: <sip:1151@172.25.40.165:5060>
Supported: timer
Content-Length: 0

 

At this point, CUCM is now satisfied and sends out an Invite to establish audio with the agent:

77978290.001 |15:16:20.506 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989393,NET]
INVITE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f818164780
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:20 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Supported: timer,resource-priority,replaces
Min-SE:  1800
Cisco-Guid: 1090515800-3470201315-2443690124-1625683936
User-Agent: Cisco-CUCM9.1
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 106 INVITE
Max-Forwards: 70
Expires: 180
Allow-Events: presence
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires:  1800;refresher=uac
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

CUCM doesn't get a 100 Trying from CUBE before 500ms timer expires:

77978308.001 |15:16:21.012 |AppInfo  |//SIP/SIPHandler/ccbId=0/scbId=0/wait_SIPTimer: TimerExpired type=SIP_TIMER_TRYING value=500 retries=6

 

 

This results in CUCM re-sending the Re-Invite:

77978310.001 |15:16:21.013 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989396,NET]
INVITE sip:20020053@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f818164780
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:21 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Supported: timer,resource-priority,replaces
Min-SE:  1800
Cisco-Guid: 1090515800-3470201315-2443690124-1625683936
User-Agent: Cisco-CUCM9.1
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 106 INVITE
Max-Forwards: 70
Expires: 180
Allow-Events: presence
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires:  1800;refresher=uac
P-Asserted-Identity: "Stephanie Vercraeye" <sip:1151@172.25.63.122>
Remote-Party-ID: "Stephanie Vercraeye" <sip:1151@172.25.63.122>;party=calling;screen=yes;privacy=off
Contact: <sip:+3236401111@172.25.63.122:5060>
Content-Length: 0

 

Now we get the 100 Trying from CUBE:

77978316.001 |15:16:21.307 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 443 from 172.25.40.165:[63621]:
[1989397,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f818164780
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:21 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
CSeq: 106 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-15.2.4.M4
Content-Length: 0

 

Then we get the 200OK from CUBE:

77978322.001 |15:16:21.309 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 1194 from 172.25.40.165:[63621]:
[1989398,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2f818164780
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:21 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
CSeq: 106 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: <sip:+32498611742@172.25.40.165>;party=called;screen=yes;privacy=off
Contact: <sip:1151@172.25.40.165:5060>
Supported: replaces
Supported: sdp-anat
Server: Cisco-SIPGateway/IOS-15.2.4.M4
Require: timer
Session-Expires:  1800;refresher=uac
Supported: timer
Content-Type: application/sdp
Content-Length: 382

v=0
o=CiscoSystemsSIP-GW-UserAgent 9504 366 IN IP4 172.25.40.165
s=SIP Call
c=IN IP4 172.25.40.165
t=0 0
m=audio 24904 RTP/AVP 8 18 0 100 101 19
c=IN IP4 172.25.40.165
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:0 PCMU/8000
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:19 CN/8000

 

Agent phone told to start transmitting media:

77978349.001 |15:16:21.313 |AppInfo  |StationD:    (0117045) startMediaTransmission conferenceID=26075143 passThruPartyID=16903885 remoteIpAddress=IpAddr.type:0 ipAddr:0xac1928a5000000000000000000000000(172.25.40.165) remotePortNumber=24904 milliSecondPacketSize=20 compressType=4(Media_Payload_G711Ulaw64k) RFC2833PayloadType=101 qualifierOut=?. myIP: IpAddr.type:0 ipv4Addr:0xac1928b4(172.25.40.180) 

 

 

OpenReceiveChannelAck from the agent's phone gives the SIP side info on where to send it's RTP stream:

77978367.001 |15:16:21.384 |AppInfo  |StationInit: (0117045) OpenReceiveChannelAck Status=0, IpAddr=IpAddr.type:0 ipAddr:0xac1928b4000000000000000000000000(172.25.40.180), Port=30252, PartyID=16903885

 

 

77978398.001 |15:16:21.390 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 172.25.40.165:[5060]:
[1989402,NET]
ACK sip:1151@172.25.40.165:5060 SIP/2.0
Via: SIP/2.0/UDP 172.25.63.122:5060;branch=z9hG4bK5b2fa53810a7a
From: <sip:+3236401111@172.25.63.122>;tag=593852~b068c976-41f2-4ce7-99ec-14d731ce5bd3-26075131
To: <sip:+32498611742@172.25.40.165>;tag=1085D008-17C
Date: Tue, 29 Apr 2014 13:16:21 GMT
Call-ID: 4101C868-CED711E3-97F693AC-312E0A47@172.25.40.165
Max-Forwards: 70
CSeq: 106 ACK
Allow-Events: presence, kpml
Content-Type: application/sdp
Content-Length: 239

v=0
o=CiscoSystemsCCM-SIP 593852 5 IN IP4 172.25.63.122
s=SIP Call
c=IN IP4 172.25.40.180
b=TIAS:64000
b=AS:64
t=0 0
m=audio 30252 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

 

We now have 2-way audio with the agent about 3 seconds after they answered the call.

 

The cause is that the CUBE is slow to respond to the Update messages for some reason.  There may be high CPU on the CUBE that is causing this.  The timer of 1000ms isn't enough resulting in the Updates being sent out again causing even more delay.

 

I would grab a "debug ccsip messages" on the CUBE for one of these calls to see what the cause of delay is.  Check the CPU/memory usage on the CUBE as well.

 

As a workaround, you could remove UPDATE from the Allow header on CUBE which will get rid of CUCM sending the Updates in the first place:

 

voice class sip-profiles 1 
request REINVITE sip-header Allow-Header modify "UPDATE, " " " 
request INVITE sip-header Allow-Header modify " UPDATE, " " " 
response 180 sip-header Allow-Header modify " UPDATE, " " " 
response 200 sip-header Allow-Header modify " UPDATE, " " " 

 

You can then apply that globally or just on your outbound dial-peers to CUCM.

 

Here's how to apply it globally:

voice service voip 

 sip

  sip-profiles 1

There were some debugs on the voice gateway that were forgotten to be disabled. Disabling these, users report they have no more issues.

Excellent detailed response, much appreciated contribution.