DTMF Interworking when Transcoding

eric.butcher · ‎12-12-2015

I currently have an enterprise sip solution from a provider that offers only g711 and only RFC2833 for DTMF.

Calls from this provider come in via 3945E CUBE with locally registered transcoder profile with RFC2833 and then are sent on to CUCM with the DTMF switched to sip-notify.

All calls on this solution ring in to UCCX in g711 mode.

Some of our agents are at remote sites with bandwidth constraints requiring the use of g729, and after a caller makes it through our IVR system and is routed to one of these remote agents, the CUBE invokes a transcoder session for the duration of the call.

In some cases, at the end of a call, our agent will need to transfer the caller back into our IVR system to make credit card payments. When this happens, since the transcoder stays in place once invoked, we lose our DTMF Interworking between RFC2833 and sip-notify.

Does anybody know how to remedy this?

The CUBE is using RTP-RTP Flowthrough and here is a breakdown of the call:

PSTN => Telco =SIP(g711)=> CUBE =SIP(g711)=> CUCM =JTAPI=>UCCX - No transcoding yet, DTMF works.

Upon transfer to agent, the call becomes:

PSTN => Telco =SIP(g711)=> CUBE(xcoder) =SIP(g729)=> CUCM =SCCP=> Agent Phone - Transcoding active

When the agent transfers the call back into the IVR:

PSTN => Telco =SIP(g711)=> CUBE(xcoder) =SIP(g711)=> CUCM =JTAPI=> UCCX - Transcoder still in the call path, no DTMF

Will placing an MTP in here somewhere resolve this issue? If so, does it have to be on every call or will it invoke the MTP when needed?

Ayodeji Okanlawon · ‎12-12-2015

Hi Eric,

I don't see how the transcoder will remain in the call path after the agent transfers the call back to the IVR. When the transfer happens, media is disconnected from the agent and new media negotiation is done between the IVR and PSTN.

We will need cucm logs to determine why DTMF doesn't work after the transfer.

Can you send us the logs. Please use this document to see how to collect cucm logs.

https://supportforums.cisco.com/document/12724111/understanding-cucm-traces-end-endcollect cucm logs.

Check the section under collecting cucm logs and you should use the relevant version of cucm to you. Please include call details calling, called number and time of call.

Please rate all useful posts

eric.butcher · ‎12-14-2015

Unfortunately, uploading the logs potentially exposes payment card and other personal information. The messages in the call setup for the transfer back to the IVR are:

29216827.001 |14:38:16.531 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[34775997,NET]
INVITE sip:[NUMBER_CALLING]@[CUBE_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc073afd51f9
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:16 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
Supported: timer,resource-priority,replaces
Cisco-Guid: 1258425618-2675249637-3089546227-1247320748
User-Agent: Cisco-CUCM10.5
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 101 INVITE
Max-Forwards: 70
Expires: 180
Allow-Events: presence
Call-Info: <sip:[CUCM_SUB_IP]:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires: 7200;refresher=uac
Min-SE: 1800
P-Asserted-Identity: <sip:[CTI_PORT_DN]@[CUCM_SUB_IP]>
Remote-Party-ID: <sip:[CTI_PORT_DN]@[CUCM_SUB_IP]>;party=calling;screen=yes;privacy=off
Contact: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]:5060>
Content-Type: application/sdp
Content-Length: 197
v=0
o=CiscoSystemsCCM-SIP 14765903 2 IN IP4 [CUCM_SUB_IP]
s=SIP Call
c=IN IP4 0.0.0.0
b=TIAS:64000
b=CT:64
b=AS:64
t=0 0
m=audio 31726 RTP/AVP 0
a=ptime:20
a=rtpmap:0 PCMU/8000
a=inactive

29216828.001 |14:38:16.532 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 452 from [CUBE_IP]:[51066]:
[34775998,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc073afd51f9
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:16 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
CSeq: 101 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-15.4.3.M3
Content-Length: 0

29216830.001 |14:38:16.532 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 1124 from [CUBE_IP]:[51066]:
[34775999,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc073afd51f9
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:16 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
CSeq: 101 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;party=called;screen=no;privacy=off
Contact: <sip:[NUMBER_CALLING]@[CUBE_IP]:5060>
Supported: replaces
Call-Info: <sip:[CUBE_IP]:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
Supported: sdp-anat
Server: Cisco-SIPGateway/IOS-15.4.3.M3
Require: timer
Session-Expires: 7200;refresher=uac
Supported: timer
Content-Type: application/sdp
Content-Length: 200
v=0
o=CiscoSystemsSIP-GW-UserAgent 9967 4601 IN IP4 [CUBE_IP]
s=SIP Call
c=IN IP4 [CUBE_IP]
t=0 0
m=audio 29392 RTP/AVP 0
c=IN IP4 [CUBE_IP]
a=inactive
a=rtpmap:0 PCMU/8000
a=ptime:20

29216833.001 |14:38:16.533 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[34776000,NET]
ACK sip:[NUMBER_CALLING]@[CUBE_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc085193f951
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:16 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
User-Agent: Cisco-CUCM10.5
Max-Forwards: 70
CSeq: 101 ACK
Allow-Events: presence
Content-Length: 0

29219052.001 |14:38:17.952 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[34776013,NET]
UPDATE sip:[NUMBER_CALLING]@[CUBE_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc0f19fa9ecb
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:16 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
User-Agent: Cisco-CUCM10.5
Max-Forwards: 70
Supported: timer,resource-priority,replaces
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 102 UPDATE
Call-Info: <sip:[CUCM_SUB_IP]:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires: 7200;refresher=uac
Min-SE: 1800
P-Asserted-Identity: "[Agent Name]" <sip:[AGENT_EXTENSION]@[CUCM_SUB_IP]>
Remote-Party-ID: "[Agent Name]" <sip:[AGENT_EXTENSION]@[CUCM_SUB_IP]>;party=calling;screen=yes;privacy=off
Contact: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]:5060>
Content-Length: 0

29219096.001 |14:38:17.954 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 564 from [CUBE_IP]:[51066]:
[34776014,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc0f19fa9ecb
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:17 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
Server: Cisco-SIPGateway/IOS-15.4.3.M3
CSeq: 102 UPDATE
Allow-Events: telephone-event
Contact: <sip:[NUMBER_CALLING]@[CUBE_IP]:5060>
Require: timer
Session-Expires: 7200;refresher=uac
Supported: timer
Content-Length: 0

29219105.001 |14:38:17.955 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[34776015,NET]
INVITE sip:[NUMBER_CALLING]@[CUBE_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc1026e5dcd2
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:17 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
Supported: timer,resource-priority,replaces
Cisco-Guid: 1258425618-2675249637-3089546227-1247320748
User-Agent: Cisco-CUCM10.5
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 103 INVITE
Max-Forwards: 70
Expires: 180
Allow-Events: presence
Call-Info: <sip:[CUCM_SUB_IP]:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires: 7200;refresher=uac
Min-SE: 1800
P-Asserted-Identity: "[Agent Name]" <sip:[AGENT_EXTENSION]@[CUCM_SUB_IP]>
Remote-Party-ID: "[Agent Name]" <sip:[AGENT_EXTENSION]@[CUCM_SUB_IP]>;party=calling;screen=yes;privacy=off
Contact: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]:5060>
Content-Length: 0

29219106.001 |14:38:17.956 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 452 from [CUBE_IP]:[51066]:
[34776016,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc1026e5dcd2
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:17 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
CSeq: 103 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-15.4.3.M3
Content-Length: 0

29219108.001 |14:38:17.956 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 1159 from [CUBE_IP]:[51066]:
[34776017,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc1026e5dcd2
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:17 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
CSeq: 103 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;party=called;screen=no;privacy=off
Contact: <sip:[NUMBER_CALLING]@[CUBE_IP]:5060>
Supported: replaces
Call-Info: <sip:[CUBE_IP]:5060>;method="NOTIFY;Event=telephone-event;Duration=500"
Supported: sdp-anat
Server: Cisco-SIPGateway/IOS-15.4.3.M3
Require: timer
Session-Expires: 7200;refresher=uac
Supported: timer
Content-Type: application/sdp
Content-Length: 235
v=0
o=CiscoSystemsSIP-GW-UserAgent 9967 4602 IN IP4 [CUBE_IP]
s=SIP Call
c=IN IP4 [CUBE_IP]
t=0 0
m=audio 29392 RTP/AVP 0 18
c=IN IP4 [CUBE_IP]
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=ptime:20

29219688.001 |14:38:18.118 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[34776027,NET]
ACK sip:[NUMBER_CALLING]@[CUBE_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc157a0d9b18
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:17 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
User-Agent: Cisco-CUCM10.5
Max-Forwards: 70
CSeq: 103 ACK
Allow-Events: presence, kpml
Content-Type: application/sdp
Content-Length: 212
v=0
o=CiscoSystemsCCM-SIP 14765903 3 IN IP4 [CUCM_SUB_IP]
s=SIP Call
c=IN IP4 172.20.100.143
b=TIAS:8000
b=CT:8
b=AS:8
t=0 0
m=audio 17886 RTP/AVP 18
a=ptime:20
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no

From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:53 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
Supported: timer,resource-priority,replaces
Cisco-Guid: 1258425618-2675249637-3089546227-1247320748
User-Agent: Cisco-CUCM10.5
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
CSeq: 104 INVITE
Max-Forwards: 70
Expires: 180
Allow-Events: presence
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires: 7200;refresher=uac
Min-SE: 1800
P-Asserted-Identity: "[Agent Name]" <sip:[AGENT_EXTENSION]@[CUCM_SUB_IP]>
Remote-Party-ID: "[Agent Name]" <sip:[AGENT_EXTENSION]@[CUCM_SUB_IP]>;party=calling;screen=yes;privacy=off
Contact: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]:5060>
Content-Type: application/sdp
Content-Length: 217
v=0
o=CiscoSystemsCCM-SIP 14765903 4 IN IP4 [CUCM_SUB_IP]
s=SIP Call
c=IN IP4 0.0.0.0
b=TIAS:8000
b=CT:8
b=AS:8
t=0 0
m=audio 17886 RTP/AVP 18
a=ptime:20
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=inactive

29255962.001 |14:38:53.302 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 452 from [CUBE_IP]:[51066]:
[34776218,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc7c7cb41f48
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:53 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
CSeq: 104 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-15.4.3.M3
Content-Length: 0

29255964.001 |14:38:53.302 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 466 from [CUBE_IP]:[51066]:
[34776219,NET]
SIP/2.0 488 Not Acceptable Media
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc7c7cb41f48
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:53 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
CSeq: 104 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-15.4.3.M3
Content-Length: 0

29255966.001 |14:38:53.303 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[34776220,NET]
ACK sip:[NUMBER_CALLING]@[CUBE_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc7c7cb41f48
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:53 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
User-Agent: Cisco-CUCM10.5
Max-Forwards: 70
CSeq: 104 ACK
Allow-Events: presence
Content-Length: 0

29257915.001 |14:38:54.932 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[34776237,NET]
UPDATE sip:[NUMBER_CALLING]@[CUBE_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc86151b08e8
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:53 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
User-Agent: Cisco-CUCM10.5
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
Session-Expires: 7200;refresher=uac
Min-SE: 1800
P-Asserted-Identity: <sip:[CTI_PORT_EXTENSION]@[CUCM_SUB_IP]>
Remote-Party-ID: <sip:[CTI_PORT_EXTENSION]@[CUCM_SUB_IP]>;party=calling;screen=yes;privacy=off
Contact: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]:5060>
Content-Length: 0

29257961.001 |14:38:54.934 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 564 from [CUBE_IP]:[51066]:
[34776238,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc86151b08e8
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:54 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
Server: Cisco-SIPGateway/IOS-15.4.3.M3
CSeq: 105 UPDATE
Allow-Events: telephone-event
Contact: <sip:[NUMBER_CALLING]@[CUBE_IP]:5060>
Require: timer
Session-Expires: 7200;refresher=uac
Supported: timer
Content-Length: 0

29257970.001 |14:38:54.935 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[34776239,NET]
INVITE sip:[NUMBER_CALLING]@[CUBE_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc87278c5970
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:54 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
Supported: timer,resource-priority,replaces
Cisco-Guid: 1258425618-2675249637-3089546227-1247320748
User-Agent: Cisco-CUCM10.5
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: 7200;refresher=uac
Min-SE: 1800
P-Asserted-Identity: <sip:[CTI_PORT_EXTENSION]@[CUCM_SUB_IP]>
Remote-Party-ID: <sip:[CTI_PORT_EXTENSION]@[CUCM_SUB_IP]>;party=calling;screen=yes;privacy=off
Contact: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]:5060>
Content-Length: 0

29257971.001 |14:38:54.935 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 452 from [CUBE_IP]:[51066]:
[34776240,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc87278c5970
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:54 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
CSeq: 106 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-15.4.3.M3
Content-Length: 0

29257973.001 |14:38:54.935 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 1160 from [CUBE_IP]:[51066]:
[34776241,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc87278c5970
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:54 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
CSeq: 106 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;party=called;screen=no;privacy=off
Contact: <sip:[NUMBER_CALLING]@[CUBE_IP]:5060>
Supported: replaces
Call-Info: <sip:[CUBE_IP]:5060>;method="NOTIFY;Event=telephone-event;Duration=2000"
Supported: sdp-anat
Server: Cisco-SIPGateway/IOS-15.4.3.M3
Require: timer
Session-Expires: 7200;refresher=uac
Supported: timer
Content-Type: application/sdp
Content-Length: 235
v=0
o=CiscoSystemsSIP-GW-UserAgent 9967 4602 IN IP4 [CUBE_IP]
s=SIP Call
c=IN IP4 [CUBE_IP]
t=0 0
m=audio 29392 RTP/AVP 0 18
c=IN IP4 [CUBE_IP]
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=ptime:20

29258318.001 |14:38:55.133 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[34776249,NET]
ACK sip:[NUMBER_CALLING]@[CUBE_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUCM_SUB_IP]:5060;branch=z9hG4bKcacc8b5aab6d9e
From: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
To: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
Date: Fri, 11 Dec 2015 19:38:54 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
User-Agent: Cisco-CUCM10.5
Max-Forwards: 70
CSeq: 106 ACK
Allow-Events: presence, kpml
Content-Type: application/sdp
Content-Length: 188
v=0
o=CiscoSystemsCCM-SIP 14765903 5 IN IP4 [CUCM_SUB_IP]
s=SIP Call
c=IN IP4 10.50.3.20
b=TIAS:64000
b=CT:64
b=AS:64
t=0 0
m=audio 24728 RTP/AVP 0
a=ptime:20
a=rtpmap:0 PCMU/8000

[--Call being hung up after the IVR appears to not hear any DTMF. Important to note that there were no NOTIFY messages between this message and the previous,
Indicating that the Gateway isn't bothering to send DTMF using sip-notify (the only DTMF relay method configured on the dial peer to CUCM]

29304602.003 |14:39:50.206 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 581 from [CUBE_IP]:[51066]:
[34776552,NET]
BYE sip:[NUMBER_CALLED]@[CUCM_SUB_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUBE_IP]:5060;branch=z9hG4bK10C16449
From: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
To: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
Date: Fri, 11 Dec 2015 19:38:55 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
User-Agent: Cisco-SIPGateway/IOS-15.4.3.M3
Max-Forwards: 70
Timestamp: 1449862790
CSeq: 120 BYE
Reason: Q.850;cause=16
P-RTP-Stat: PS=10550,OS=1390640,PR=10083,OR=1366740,PL=0,JI=0,LA=0,DU=207
Content-Length: 0

29304688.001 |14:39:50.209 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[34776553,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP [CUBE_IP]:5060;branch=z9hG4bK10C16449
From: "[CALLER_NAME] " <sip:[NUMBER_CALLING]@[CUBE_IP]>;tag=1DCD1012-25C8
To: <sip:[NUMBER_CALLED]@[CUCM_SUB_IP]>;tag=14765903~99cf0eaf-8a4f-4b68-b666-f468533531f5-40009478
Date: Fri, 11 Dec 2015 19:39:50 GMT
Call-ID: 4B025B26-9F7511E5-B82CBBF3-4A589AAC@[CUBE_IP]
Server: Cisco-CUCM10.5
CSeq: 120 BYE
Content-Length: 0

Ayodeji Okanlawon · ‎12-14-2015

Considering the sensitivity of your data, you might want to open a TAC case. I can't offer much help without seeing the full trace.

However in this trace, there is no DTMF attributes in the Re-INVITE or the 200 OK from Cube.

Please rate all useful posts

eric.butcher · ‎12-14-2015

I figured it out, but was mistaken in part of my initial observation. The transcoder IS being freed up during the transfer.

The dial peers between CUBE and CUCM were set to only use sip-notify. The dial peers between the provider were set to only allow rtp-nte.

When re-inviting to the IP Phone, sip-notify was not possible and since there was no fallback DTMF method, the call continued without DTMF capabilities (voice-only). When the transfer occurred, instead of renegotiating DTMF again, it renegotiated only the media.

I tried adding rtp-nte to the dial-peer after sip-notify, but the result was similar. I would negotiate rtp-nte DTMF on both legs after being transferred to the agent (so, better?), but when the agent would transfer me back to the IVR, I would once again end up with a CUBE<=>CUCM call leg that negotiated as stream-type voice-only.

By adding sip-kpml and rtp-nte to the DTMF Relay options on the dial peer (after SIP-NOTIFY), it causes KPML to be negotiated initially (since it is highest priority), and then switches to rtp-nte while I am connected to the agent, and then back to sip-kpml after the transfer back to the IVR.

I suspect this might be intended behavior but I'm not 100% sure. I thought that after the transfer it would renegotiate voice+dtmf rather than just voice, but that isn't what was happening. In addition, why would it be able to renegotiate DTMF when using KPML and not SIP-Notify? Is this a bug?

Thanks for the assist, it at least got me looking in the right neighborhood.

Ayodeji Okanlawon · ‎12-14-2015

Okay let me try and clear a few things up.

1. KPML is never the highest priority. If the endpoint can support rtp-nte regardless of the order of the preference of DTMF, rtp-nte is preferred.

Please refer to scenario 4 in this document

https://supportforums.cisco.com/document/144711/understanding-dtmf-negotiation-and-troubleshooting-sip-trunks

2. When you use rtp-nte to sip-kpml, an MTP/xcoder will be invoked. This is because CUCM/CUBE cant natively interoperate between this two DTMF methods. The only OOB DTMF method that CUBE/CUCM interoperates with is sip-notify

Please refer to the DTMF interoperability table here

http://www.cisco.com/c/en/us/td/docs/ios-xml/ios/voice/cube/configuration/cube-book/dtmf-relay.html#concept_264617919921874995299551391601561

3. You should check that when using KPML and rtp-nte, that a MTP was indeed invoked and this would change the whole dynamics of the call flow.

Please rate all useful posts

eric.butcher · ‎12-14-2015

KPML is top preference in OOB DTMF methods, though. This causes it to negotiate kpml over sip-notify when connecting to UCCX.

^I'm actually no longer able to find the documentation that I read this in...

Found it:

For incoming dial peers, the first out-of-band negotiation method takes precedence over other DTMF negotiation methods, except when the dtmf-relay rtp-ntecommand has precedence; in this case, the dtmf-relay sip-kpml command takes precedence over other out-of-band negotiation methods.

Under restrictions HERE: http://www.cisco.com/c/en/us/td/docs/ios-xml/ios/voice/sip/configuration/15-mt/sip-config-15-mt-book/voi-sip-dtmf.html

I saw on the RTP-RTP flow through scenario... indeed, rtp-nte to KPML doesn't appear to be supported for DTMF Interworking in this scenario. However, I see no evidence a transcoder or MTP is being invoked:

LB-3945E-CUBE#show call active voice compact
 <callID> A/O FAX T<sec> Codec type Peer Address IP R<ip>:<udp>
Total call-legs: 2
 44179 ANS T3 g711ulaw VOIP P[0CALLING] [PROVIDER_IP]:26288
 44180 ORG T3 g711ulaw VOIP P[00CALLED] [UCCX_IP]:27460

^The CUBE has 2 call legs, one incoming from the provider and one outgoing and terminated at the UCCX Primary server. If CUCM was somehow bypassing my MRGL configuration and invoking an MTP, wouldn't the MTP show up in one of these IP Addresses?

LB-3945E-CUBE#show dspfarm all | ex -
Dspfarm Profile Configuration

Profile ID = 1, Service = TRANSCODING, Resource ID = 1
 Profile Service Mode : Non Secure
 Profile Admin State : UP
 Profile Operation State : ACTIVE
 Application : CUBE Status : ASSOCIATED
 Resource Provider : FLEX_DSPRM Status : UP
 Number of Resource Configured : 148
 Number of Resources Out of Service : 0
 Number of Resources Active : 0
 Codec Configuration: num_of_codecs:3
 Codec : g729r8, Maximum Packetization Period : 60
 Codec : g711ulaw, Maximum Packetization Period : 30
 Codec : g729ar8, Maximum Packetization Period : 60

SLOT DSP VERSION STATUS CHNL USE TYPE RSC_ID BRIDGE_ID PKTS_TXED PKTS_RXED

Total number of DSPFARM DSP channel(s) 148

^The sip trunk in CUCM is isolated with a MRGL that has no transcoding or media termination resources in it, so it can only use its local transcoder (Associated to the CUBE application instead of SCCP). There are no active sessions on the transcoder, however.

LB-3945E-CUBE#show sip-ua calls calling-number [CALLING_PARTY]
Total SIP call legs:6, User Agent Client:3, User Agent Server:3
SIP UAC CALL INFO
Call 1
SIP Call ID : BB49B306-A1C711E5-AF34BBF3-4A589AAC@[CUBE_IP]
 State of the call : STATE_ACTIVE (7)
 Substate of the call : SUBSTATE_NONE (0)
 Calling Number : [CALLING_PARTY]
 Called Number : [CALLED_PARTY]
 Called URI : sip:[CALLED_PARTY]@[CUCM_SUB_IP]
 Bit Flags : 0xC04018 0x90000100 0x80
 CC Call ID : 44180
 Source IP Address (Sig ): [CUBE_IP]
 Destn SIP Req Addr:Port : [CUCM_SUB_IP]:5060
 Destn SIP Resp Addr:Port: [CUCM_SUB_IP]:5060
 Destination Name : [CUCM_SUB_IP]
 Number of Media Streams : 1
 Number of Active Streams: 1
 RTP Fork Object : 0x0
 Media Mode : flow-through
 Media Stream 1
 State of the stream : STREAM_ACTIVE
 Stream Call ID : 44180
 Stream Type : voice-only (0)
 Stream Media Addr Type : 1
 Negotiated Codec : g711ulaw (160 bytes)
 Codec Payload Type : 0
 Negotiated Dtmf-relay : sip-kpml
 Dtmf-relay Payload Type : 0
 QoS ID : -1
 Local QoS Strength : BestEffort
 Negotiated QoS Strength : BestEffort
 Negotiated QoS Direction : None
 Local QoS Status : None
 Media Source IP Addr:Port: [CUBE_IP]:30228
 Media Dest IP Addr:Port : [UCCX_IP]:27460

Options-Ping ENABLED:NO ACTIVE:NO
 Number of SIP User Agent Client(UAC) calls: 1

SIP UAS CALL INFO
Call 1
SIP Call ID : 667ea242.6400320a.566f0b03.b4471
 State of the call : STATE_ACTIVE (7)
 Substate of the call : SUBSTATE_NONE (0)
 Calling Number : [CALLING_PARTY]
 Called Number : [CALLED_PARTY]
 Called URI : sip:[CALLED_PARTY]@[CUBE_IP]:5060
 Bit Flags : 0xC0401C 0x10000100 0x4
 CC Call ID : 44179
 Source IP Address (Sig ): [CUBE_IP]
 Destn SIP Req Addr:Port : [PROVIDER_IP]:5060
 Destn SIP Resp Addr:Port: [PROVIDER_IP]:5060
 Destination Name : [PROVIDER_IP]
 Number of Media Streams : 1
 Number of Active Streams: 1
 RTP Fork Object : 0x0
 Media Mode : flow-through
 Media Stream 1
 State of the stream : STREAM_ACTIVE
 Stream Call ID : 44179
 Stream Type : voice+dtmf (0)
 Stream Media Addr Type : 1
 Negotiated Codec : g711ulaw (160 bytes)
 Codec Payload Type : 0
 Negotiated Dtmf-relay : rtp-nte
 Dtmf-relay Payload Type : 101
 QoS ID : -1
 Local QoS Strength : BestEffort
 Negotiated QoS Strength : BestEffort
 Negotiated QoS Direction : None
 Local QoS Status : None
 Media Source IP Addr:Port: [CUBE_IP]:30226
 Media Dest IP Addr:Port : [PROVIDER_IP]:26288

Options-Ping ENABLED:NO ACTIVE:NO
 Number of SIP User Agent Server(UAS) calls: 1

^DTMF seems to clearly be sip-kpml on one leg and rtp-nte on the other leg. Media termination IP Addresses are Provider, CUBE, and UCCX (transcoder only configured on CUBE, and if it was invoking CUCM MTP I would expect the media address on the leg to point to one of the CUCM servers).

What am I missing here?

According to this: http://www.cisco.com/c/en/us/td/docs/ios-xml/ios/voice/cube/configuration/cube-book/dtmf-relay.html

It shouldn't be able to do rtp-nte to sip-kpml interworking in RTP-RTP Flow Through, as you pointed out... But it seems to be, and the IVR processes my DTMF.

Ayodeji Okanlawon · ‎12-14-2015

KPML is top preference in OOB DTMF methods, though. This causes it to negotiate kpml over sip-notify when connecting to UCCX.

Yes indeed KPML is the preferred in OOB, however I said if both endpoints support rtp-nte, the preference is ignored on the dial-peer and rtp-nte will be used.

KPML is used here simply because UCCX cti ports cant support rtp-nte.

KPML is top preference in OOB DTMF methods, though. This causes it to negotiate kpml over sip-notify when connecting to UCCX.

2. Very good observation. sip-kpml---> rtp-nte ( this is clearly OOB to In-band) and in previous cucm version (atleast 9.1.2) you would need MTP for this. It is possible that this is a new enhancement in cucm 10.5.

A cucm trace would definitely confirm this. You can look through the logs yourself and look for this field "isMTPNeededForMismatchOrConfig"

You should see a similar trace like this..albeit yours should be different since MTP is not invoked..

00028211.015 |12:59:46.338 |AppInfo |DET-MediaManager-(13)::isMTPNeededForMismatchOrConfig, MTPNeededDueToDTMFCapMismatch(2833/OOB) mtpinsertionReason=1 dtmfMTPSide=2

I am keen to find out what you see..

Please rate all useful posts

eric.butcher · ‎12-15-2015

There is no "isMTPNeededForMisMatchOrConfig" line for the test calls I made, but to make sure it wasn't just due to my trace settings, I did cast a wide net. There are MTP's being allocated for a specific call flow for one of my remote offices (without agents) who are placing outbound calls through a PRI gateway across the wan (had no choice unfortunately)... But here are relevant traces with my test call and the media negotiation. Its clearly negotiating KPML as the DTMF and on the gateway debugs the media addresses were consistent with my previous results:

06259060.002 |09:56:35.876 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 1311 from [CUBE_IP]:[51066]:
[66557,NET]
INVITE sip:[CALLED_PARTY]@[CUCM_SUB] SIP/2.0
Via: SIP/2.0/UDP [CUBE_IP]:5060;branch=z9hG4bK11C191B4
Remote-Party-ID: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;party=calling;screen=no;privacy=off
From: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
To: <sip:[CALLED_PARTY]@[CUCM_SUB]>
Date: Tue, 15 Dec 2015 14:56:35 GMT
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
Supported: 100rel,timer,resource-priority,replaces,sdp-anat
Min-SE: 1800
Cisco-Guid: 3744086586-2725384677-2182003699-1247320748
User-Agent: Cisco-SIPGateway/IOS-15.4.3.M3
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
CSeq: 101 INVITE
Timestamp: 1450191395
Contact: <sip:[CALLING_PARTY]@[CUBE_IP]:5060>
Call-Info: <sip:[CUBE_IP]:5060>;method="NOTIFY;Event=telephone-event;Duration=2000"
Expires: 180
Allow-Events: kpml, telephone-event
Max-Forwards: 69
Content-Type: application/sdp
Content-Disposition: session;handling=required
Content-Length: 291
v=0
o=CiscoSystemsSIP-GW-UserAgent 3355 5677 IN IP4 [CUBE_IP]
s=SIP Call
c=IN IP4 [CUBE_IP]
t=0 0
m=audio 30910 RTP/AVP 0 18 101
c=IN IP4 [CUBE_IP]
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

06259063.003 |09:56:35.878 |AppInfo |SIPCdpc(3656) - StartTransition: BFCPAllowed=0 allowMultiCodecsInAnswer = 0, ACROutgoing=0 ACRIncoming=0 honorIncomingCodecPref=0
06259063.004 |09:56:35.878 |AppInfo |SIPCdpc(3656) - StartTransition: requireInactiveSDPForMidcallMediaChange=0, isTrunkEnabledForVoiceEO=0, mSipMcuControl 0 addrMode 0 ANAT=0

06259064.001 |09:56:35.879 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[66558,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/UDP [CUBE_IP]:5060;branch=z9hG4bK11C191B4
From: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
To: <sip:[CALLED_PARTY]@[CUCM_SUB]>
Date: Tue, 15 Dec 2015 14:56:35 GMT
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
CSeq: 101 INVITE
Allow-Events: presence
Content-Length: 0

06259065.006 |09:56:35.879 |AppInfo |SIPCdpc(3656) - preProcessOffer: audiomLines[0]: rtp=1,srtp=0,deviceNOTSrtpCapable=1,numCrypto=0,isOfferFromCCM=0,sipEndpointCanRcvSrtpOffers=0,deviceSupportsSrtpFB=0,telephone-event=101
06259065.007 |09:56:35.879 |AppInfo |SIPCdpc(3656) - updateAllowedMethods: mEndpointAllowedMethods=07ff

06259069.001 |09:56:35.879 |AppInfo |SIPCdpc(3656) - isMidCallFallbackSupported: getXCiscoViPRFallbackID returned false, proceed without PSTN fallback
06259069.002 |09:56:35.879 |AppInfo |SIPCdpc(3656) - getDefAe: SIPCdpc=3656, nodeId=2, processNumber=81 ci=46062634, branch=0
06259069.003 |09:56:35.879 |AppInfo |SIPCdpc(3656) - sendPolicyAndCACRegisterReq: capCount[3], videoCap[0], dataCap[0], MMCap[01], earlyOffer[2], latCaps[NULL]
06259069.004 |09:56:35.879 |AppInfo |DET-SDPMsg- sBandwidth:: enabledMask=0x0 as=0 ct=0 tias=0 maxprate=0
06259069.005 |09:56:35.879 |AppInfo |DET-SDPMsg- sipp: ispres=1, role=1 vers=162d anat=0
06259069.006 |09:56:35.879 |AppInfo |DET-SDPMsg- ngroups 0
06259069.007 |09:56:35.879 |AppInfo |DET-SDPMsg- No Session level unrecognized attributes list.
06259069.008 |09:56:35.879 |AppInfo |DET-SDPMsg- nAudio=1, mDTMFP.PayloadNum=0
06259069.009 |09:56:35.879 |AppInfo |DET-SDPMsg- remoteIpAddr=[CUBE_IP] remoteRtpPortNumber=30910 stackIdx=1 telephonyEvent=101 silenceSuppressionFlag=0 mSDPMode=0 idleFlag=0 mid=-1
06259069.010 |09:56:35.879 |AppInfo |DET-SDPMsg- CurrentStatus:: present=0 QoSStatusType=0 QoSDirectionTag=0 
06259069.011 |09:56:35.879 |AppInfo |DET-SDPMsg- DesiredStatus:: present=0 QoSStatusType=0 QoSDirectionTag=0 QoSStrengthTag=2 
06259069.012 |09:56:35.879 |AppInfo |DET-SDPMsg- ConfirmStatus:: present=0 QoSStatusType=0 QoSDirectionTag=0 
06259069.013 |09:56:35.879 |AppInfo |DET-SDPMsg- RTP=1 SRTP=0 CapCount=3 
06259069.014 |09:56:35.879 |AppInfo |DET-SDPMsg-4(20) 
06259069.015 |09:56:35.879 |AppInfo |DET-SDPMsg-11(20) 
06259069.016 |09:56:35.879 |AppInfo |DET-SDPMsg-12(20) 
06259069.017 |09:56:35.879 |AppInfo |DET-SDPMsg-v150LC(0,pt=0) t38LC(0) 
06259069.018 |09:56:35.879 |AppInfo |DET-SDPMsg- TCL_UNSPECIFIED (0) 
06259069.019 |09:56:35.879 |AppInfo |DET-SDPMsg- No unrecognized attributes list.
06259069.020 |09:56:35.879 |AppInfo |DET-SDPMsg- mAudiomLines(i).bandwidth.enabledMask=, TIAS=0, AS=0, CT=0, RS=0, RR=0
06259069.021 |09:56:35.879 |AppInfo |DET-SDPMsg- nVideo=0
06259069.022 |09:56:35.879 |AppInfo |DET-SDPMsg- nApp=0
06259069.023 |09:56:35.879 |AppInfo |DET-SDPMsg- nBFCPApp=0
06259069.024 |09:56:35.879 |AppInfo |DET-SDPMsg- nIXApp=0

06259073.001 |09:56:35.879 |AppInfo |RSVP(2,21893) -await_init_RSVPRegisterReq- SDPMsg
06259073.002 |09:56:35.879 |AppInfo |DET-SDPMsg- sBandwidth:: enabledMask=0x0 as=0 ct=0 tias=0 maxprate=0
06259073.003 |09:56:35.879 |AppInfo |DET-SDPMsg- sipp: ispres=1, role=1 vers=162d anat=0
06259073.004 |09:56:35.879 |AppInfo |DET-SDPMsg- ngroups 0
06259073.005 |09:56:35.879 |AppInfo |DET-SDPMsg- No Session level unrecognized attributes list.
06259073.006 |09:56:35.879 |AppInfo |DET-SDPMsg- nAudio=1, mDTMFP.PayloadNum=0
06259073.007 |09:56:35.879 |AppInfo |DET-SDPMsg- remoteIpAddr=[CUBE_IP] remoteRtpPortNumber=30910 stackIdx=1 telephonyEvent=101 silenceSuppressionFlag=0 mSDPMode=0 idleFlag=0 mid=-1
06259073.008 |09:56:35.879 |AppInfo |DET-SDPMsg- CurrentStatus:: present=0 QoSStatusType=0 QoSDirectionTag=0 
06259073.009 |09:56:35.879 |AppInfo |DET-SDPMsg- DesiredStatus:: present=0 QoSStatusType=0 QoSDirectionTag=0 QoSStrengthTag=2 
06259073.010 |09:56:35.879 |AppInfo |DET-SDPMsg- ConfirmStatus:: present=0 QoSStatusType=0 QoSDirectionTag=0 
06259073.011 |09:56:35.879 |AppInfo |DET-SDPMsg- RTP=1 SRTP=0 CapCount=3 
06259073.012 |09:56:35.879 |AppInfo |DET-SDPMsg-4(20) 
06259073.013 |09:56:35.879 |AppInfo |DET-SDPMsg-11(20) 
06259073.014 |09:56:35.879 |AppInfo |DET-SDPMsg-12(20) 
06259073.015 |09:56:35.879 |AppInfo |DET-SDPMsg-v150LC(0,pt=0) t38LC(0) 
06259073.016 |09:56:35.879 |AppInfo |DET-SDPMsg- TCL_UNSPECIFIED (0) 
06259073.017 |09:56:35.879 |AppInfo |DET-SDPMsg- No unrecognized attributes list.
06259073.018 |09:56:35.879 |AppInfo |DET-SDPMsg- mAudiomLines(i).bandwidth.enabledMask=, TIAS=0, AS=0, CT=0, RS=0, RR=0
06259073.019 |09:56:35.879 |AppInfo |DET-SDPMsg- nVideo=0
06259073.020 |09:56:35.879 |AppInfo |DET-SDPMsg- nApp=0
06259073.021 |09:56:35.879 |AppInfo |DET-SDPMsg- nBFCPApp=0
06259073.022 |09:56:35.879 |AppInfo |DET-SDPMsg- nIXApp=0

06259074.000 |09:56:35.879 |SdlSig |RSVPRegisterRes |wait |ReservationMgr(2,100,110,1) |RSVPSession(2,100,107,21893) |2,100,10,1.7596^[CUBE_IP]^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI= 46062634 Branch= 0 Status=1 rsvpPol=0 vCall=F e2eRSVPInserted=F eoStatus=0 mediaFailureCause=0 mediaPassThruCapable=T fallbackLocal=F hasSDPMsg=F DevicecontrolPid=2,100,82,3656 DeviceCdpcPid=2,100,82,3656 RSVPAgent: confID =0 ci =0 capCt =0 reg= mtpType =2 agentCt =0 mmCapSet=0 agentAllo =0 RemoAgent=F DevCap=0 ipAddrMode=0

06259075.000 |09:56:35.879 |SdlSig |PolicyAndCACRegisterRes |inCall_waitRSVPRes |SIPCdpc(2,100,82,3656) |ReservationMgr(2,100,110,1) |2,100,10,1.7596^[CUBE_IP]^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI= 46062634 Branch= 0 Status=1 Status=1 rsvpPol=0 vCall=F e2eRSVPInserted=F eoStatus=0 mediaFailureCause=0 mediaPassThruCapable=T fallbackLocal=F hasSDPMsg=F DevicecontrolPid=2,100,82,3656 DeviceCdpcPid=2,100,82,3656 RSVPAgent: confID =0 ci =0 capCt =0 reg= mtpType =2 agentCt =0 mmCapSet=0 agentAllo =0 RemoAgent=F DevCap=0 ipAddrMode=0 LBMCACReturnInfo: lbmReservedKbps=0 locationIsPhantom=F bwPreemption=F CAL={v=-1, m=-1, tDev=F, res=F, devType=0}
06259075.001 |09:56:35.879 |AppInfo |setEndpointsDtmfCaps: Found Call-info header <sip:[CUBE_IP]:5060>;method="NOTIFY;Event=telephone-event;Duration=2000"
06259075.002 |09:56:35.879 |AppInfo |setEndpointsDtmfCaps: Parsing done. ciUri=sip:[CUBE_IP]:5060, ciFeature=6, ciDuration=2000
06259075.003 |09:56:35.879 |AppInfo |setEndpointsDtmfCaps: KPML Supported.
06259075.004 |09:56:35.879 |AppInfo |setEndpointsDtmfCaps: Detected inband DTMF support.
06259075.005 |09:56:35.879 |AppInfo |SIP DTMF Info: mLocalDtmfCaps...UNSOL=1, KPML=0, Inband=0(0) mEndppointsDtmfCaps...UNSOL=1, KPML=1, Inband=1(101) mDefaultTelephonyEvent=101, mDtmfPreference=1, mMtpAllocated=0

06259109.000 |09:56:35.881 |SdlSig |CtiEnableReq |null0 |StationCdpc(2,100,64,11614) |StationD(2,100,63,882) |2,100,10,1.7596^[CUBE_IP]^* |[R:N-H:0,N:2,L:0,V:0,Z:0,D:0] mDataCount=1 LH=1|2619 mbMore=T bConsultWithoutMedia=F mediaTerm=0

06259280.001 |09:56:35.897 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[66559,NET]
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP [CUBE_IP]:5060;branch=z9hG4bK11C191B4
From: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
To: <sip:[CALLED_PARTY]@[CUCM_SUB]>;tag=31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
Date: Tue, 15 Dec 2015 14:56:35 GMT
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
CSeq: 101 INVITE
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
Allow-Events: presence
Server: Cisco-CUCM10.5
Supported: X-cisco-srtp-fallback
Supported: Geolocation
P-Asserted-Identity: <sip:+13170009234@[CUCM_SUB]>
Remote-Party-ID: <sip:+13170009234@[CUCM_SUB]>;party=called;screen=yes;privacy=off
Contact: <sip:[CALLED_PARTY]@[CUCM_SUB]:5060>
Content-Length: 0

06259293.000 |09:56:35.902 |SdlSig |CcUpdateRegistration |restart0 |LineControl(2,100,174,844) |StationCdpc(2,100,64,11615) |1,200,13,32.23783^[UCCX_PUB]^CC_13170009234 |[R:N-H:0,N:6,L:0,V:0,Z:0,D:0] CI=46062637 CI.branch=0 CSS=2a48566b-6bd7-e5c7-3751-d6aa04bb9a41 AdjunctCSS= cssIns=0 aarCSS= aarDev=T FQDN=ti=1nd=+13170009234pi=0si1 CallRef=0 OLC=0 Name=locale: 1 Name: UnicodeName: pi: 1 encodeType=0 qsig-encodeType=10 ConnType=3 XferMode=4 ConnTime=3 nwLoc=0IpAddrMode=0 ipAddrType=0 ipv4=0.0.0.0:0 region=ZP_UCCX capCount=2 devType=4 mixerCId=0 mediaReq=0 portToPort.loc=1 MOH.MRGLPkid=15090c43-f224-e07f-37a8-4ec74e29f09d MOH.userHoldID=0 MOH.netHoldID=0 MOH.supp=0 devName=CC_13170009234 mobileDevName= mobilePartyNumber=pi=0si1 mobileCallType=0 ctiActive=F ctiFarEndDev=1 ctiCCMId=2 devCepn=f3b7f82e-ba45-4336-a026-df425e6d86c9 lineCepn=344dce0d-73a5-f077-fecb-c00a6781ca78 activeCaps=0 VideoCall=F MMUpdateCapMask=0x3e MMCap=0x1 SipConfig: BFCPAllowed=F IXAllowed=F devCap=0 CryptoCapCount=0 secure=1 loginId= UnicodeName: retriedVideo=FFromTag=99cf0eaf-8a4f-4b68-b666-f468533531f5-46062637ToTag=99cf0eaf-8a4f-4b68-b666-f468533531f5-46062637CallId=11615@[CUCM_SUB] UAPortFlag=F wantDTMFRecep=1 provOOB=0 supp DTMF=1 DTMF Cfg=1 DTMF PT=0 DTMF reqMed=1 isPrefAltScript=F cdpnPatternUsage=-313961216 audioPtyId=0 doNotAppendLineCSS=F callingDP=6ebe77d5-cc92-f4b1-7988-ce429963d135 BCUpdate=1 ccBearCap.itc=0 ccBearCap.l=0 ccBearCap.itr=0 protected=1 flushCapIns=0 geolocInfo={geolocPkid=, filterPkid=, geolocVal=, devType=4} locPkid= locName= deductBW=F fateShareId= videoTrafficClass=Unspecified bridgeParticipantID callingUsr= remoteClusterID= isEMCCDevice=F dtmCall=F dtmPrimaryCI=0 dtmMediaIFPid=(0,0,0,0) dtmMcNodeId=0 dtmMTPForDTMFTranslation=F emc=T QSIGIMERoute=F eo=0 eoUpdt=1 vCTCUpdt=1 honorCodec=F honorUpdt=1 finalCalledPartition= cTypeUpdt=0 BibEnabled=0 RecordingQSIGAPDUSupported=F FarEndDeviceName=LatentCaps=null icidVal= icidGenAddr= oioi= tioi= ptParams= CAL={v=-1, m=-1, tDev=F, res=F, devType=0} displayNameUpdateFieldFlag=0 CFBCtrlSecIcon=F

06259300.000 |09:56:35.902 |SdlSig |CcUpdateRegistration |call_received7 |LineCdpc(2,100,175,11632) |LineControl(2,100,174,844) |1,200,13,32.23783^[UCCX_PUB]^CC_13170009234 |[R:N-H:0,N:4,L:0,V:0,Z:0,D:0] CI=46062637 CI.branch=0 CSS=:2a48566b-6bd7-e5c7-3751-d6aa04bb9a41 AdjunctCSS= cssIns=0 aarCSS= aarDev=T FQDN=ti=1nd=+13170009234pi=0si1 CallRef=0 OLC=0 Name=locale: 1 Name: UnicodeName: pi: 1 encodeType=0 qsig-encodeType=10 ConnType=3 XferMode=4 ConnTime=3 nwLoc=0IpAddrMode=0 ipAddrType=0 ipv4=0.0.0.0:0 region=ZP_UCCX capCount=2 devType=4 mixerCId=0 mediaReq=0 portToPort.loc=1 MOH.MRGLPkid=15090c43-f224-e07f-37a8-4ec74e29f09d MOH.userHoldID=0 MOH.netHoldID=0 MOH.supp=0 devName=CC_13170009234 mobileDevName= mobilePartyNumber=pi=0si1 mobileCallType=0 ctiActive=F ctiFarEndDev=1 ctiCCMId=2 devCepn=f3b7f82e-ba45-4336-a026-df425e6d86c9 lineCepn=344dce0d-73a5-f077-fecb-c00a6781ca78 activeCaps=0 VideoCall=F MMUpdateCapMask=0x3e MMCap=0x1 SipConfig: BFCPAllowed=F IXAllowed=F devCap=0 CryptoCapCount=0 secure=1 loginId= UnicodeName: retriedVideo=FFromTag=99cf0eaf-8a4f-4b68-b666-f468533531f5-46062637ToTag=99cf0eaf-8a4f-4b68-b666-f468533531f5-46062637CallId=11615@[CUCM_SUB] UAPortFlag=F wantDTMFRecep=1 provOOB=0 supp DTMF=1 DTMF Cfg=1 DTMF PT=0 DTMF reqMed=1 isPrefAltScript=F cdpnPatternUsage=-313961216 audioPtyId=0 doNotAppendLineCSS=F callingDP=6ebe77d5-cc92-f4b1-7988-ce429963d135 BCUpdate=1 ccBearCap.itc=0 ccBearCap.l=0 ccBearCap.itr=0 protected=1 flushCapIns=0 geolocInfo={geolocPkid=, filterPkid=, geolocVal=, devType=4} locPkid= locName= deductBW=F fateShareId= videoTrafficClass=Unspecified bridgeParticipantID callingUsr= remoteClusterID= isEMCCDevice=F dtmCall=F dtmPrimaryCI=0 dtmMediaIFPid=(0,0,0,0) dtmMcNodeId=0 dtmMTPForDTMFTranslation=F emc=T QSIGIMERoute=F eo=0 eoUpdt=1 vCTCUpdt=1 honorCodec=F honorUpdt=1 finalCalledPartition= cTypeUpdt=0 BibEnabled=0 RecordingQSIGAPDUSupported=F FarEndDeviceName=LatentCaps=null icidVal= icidGenAddr= oioi= tioi= ptParams= CAL={v=-1, m=-1, tDev=F, res=F, devType=0} displayNameUpdateFieldFlag=0 CFBCtrlSecIcon=F

06259314.000 |09:56:35.902 |SdlSig |CcUserInfoReq |inCall_delivered |SIPCdpc(2,100,82,3656) |SIPD(2,100,81,11) |1,200,13,32.23783^[UCCX_PUB]^CC_13170009234 |[R:N-H:0,N:2,L:0,V:0,Z:0,D:0] CI=46062634 CI.branch=0 isDtmf=F isTone=F tone=0 duration=0 PortToPort=2 isFeat=F isMTPPassThru2833=F featType=0 TTLFlag=F TTLCount=0

06259315.000 |09:56:35.902 |SdlSig |SsDataInd |awaitingCallResponse |Forwarding(2,100,198,4291) |ForwardManager(2,100,199,1) |1,200,13,32.23783^[UCCX_PUB]^CC_13170009234 |[R:N-H:0,N:1,L:0,V:0,Z:0,D:0] SsType=33554438 SsKey=0 SsNode=2 SsParty=46062637 DevId=(0,0,0) BCC=5 OtherParty=46062634 NodeOtherParty=2 clearType = 0 CSS=fe438f55-3eab-0799-3a33-64d0479bda67 CNumInfo = 0 CNameInfo = 0 ssDevType=4 ssOtherDevType=8 FDataType=0opId=0ssType=0 SsKey=0invokeId=0resultExp=Fbpda=F ssCause = 0 ssUserState = 2 ssOtherUserState = 2 PL=5 PLDmn=0 networkDomain= delayAPTimer=F geolocInfo={geolocPkid=, filterPkid=, geolocVal=, devType=4} cfwdTimerAction=0 matchInterceptPartition= matchInterceptPattern=

06259316.000 |09:56:35.902 |SdlSig |MediaConnectRequest |wait |ConnectionManager(2,100,214,1) |MatrixControl(2,100,142,22054) |1,200,13,32.23783^[UCCX_PUB]^CC_13170009234 |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] Party1: MR=0 CI=46062634 audioCapCount=3 region=Lightbound DC xferMode=16 mrid=0 audioId=0 MMCap=0x1 sipConfig: BFCPAllowed=F IXAllowed=F activeCap=0 cryptoCapCount=0 flushIns=0 dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F IFPid=(0,0,0,0) dtMedia=F honorCodec=F EOType=0 DTMF Caps(1,3,101,1,F) confID=0 connType=3 connStatus=0 mtpPre=F teleEve=0 IFCreated=F IFHandling=0 FS=0 mcNodeId=0LatentCaps=null dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F Party2: MR=0 CI=46062637 audioCapCount=2 region=ZP_UCCX xferMode=4 mrid=0 audioId=0 MMCap=0x1 sipConfig: BFCPAllowed=F IXAllowed=F activeCap=0 cryptoCapCount=0 flushIns=0 dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F IFPid=(0,0,0,0) dtMedia=F honorCodec=F EOType=0 DTMF Caps(1,1,0,1,F) confID=0 connType=3 connStatus=0 mtpPre=F teleEve=0 IFCreated=F IFHandling=0 FS=0 mcNodeId=0LatentCaps=null dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F reConnType=0 videoCall=F AllowedCallType=0x0 mtpChanged=F precLvl=5 resCap=0 party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 sideBAns= T
06259316.001 |09:56:35.902 |AppInfo |ARBTRY-ConnectionManager-wait_MediaConnectRequest(46062634,46062637)
06259316.002 |09:56:35.902 |AppInfo |ARBTRY-ConnectionManager- storeMediaInfo(CI=46062634): ADD NEW ENTRY, size=891
06259316.003 |09:56:35.902 |AppInfo |ARBTRY-ConnectionManager- storeMediaInfo(CI=46062637): ADD NEW ENTRY, size=892

06259317.000 |09:56:35.902 |SdlSig |MediaConnectRequest |wait |MediaCoordinator(2,100,141,1) |ConnectionManager(2,100,214,1) |1,200,13,32.23783^[UCCX_PUB]^CC_13170009234 |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] Party1: MR=0 CI=46062634 audioCapCount=3 region=Lightbound DC xferMode=16 mrid=0 audioId=0 MMCap=0x1 sipConfig: BFCPAllowed=F IXAllowed=F activeCap=0 cryptoCapCount=0 flushIns=0 dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F IFPid=(0,0,0,0) dtMedia=F honorCodec=F EOType=0 DTMF Caps(1,3,101,1,F) confID=0 connType=3 connStatus=0 mtpPre=F teleEve=0 IFCreated=F IFHandling=0 FS=0 mcNodeId=0LatentCaps=null dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F Party2: MR=0 CI=46062637 audioCapCount=2 region=ZP_UCCX xferMode=4 mrid=0 audioId=0 MMCap=0x1 sipConfig: BFCPAllowed=F IXAllowed=F activeCap=0 cryptoCapCount=0 flushIns=0 dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F IFPid=(0,0,0,0) dtMedia=F honorCodec=F EOType=0 DTMF Caps(1,1,0,1,F) confID=0 connType=3 connStatus=0 mtpPre=F teleEve=0 IFCreated=F IFHandling=0 FS=0 mcNodeId=0LatentCaps=null dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F reConnType=0 videoCall=F AllowedCallType=0x0 mtpChanged=F precLvl=5 resCap=0 party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 sideBAns= T
06259317.001 |09:56:35.902 |Created | | |MediaManager(2,100,140,15037) |MediaCoordinator(2,100,141,1) | |NumOfCurrentInstances: 445
06259317.002 |09:56:35.902 |AppInfo |SIG-MediaCoordinator-wait_MediaConnectRequest - new MediaManager(140,15037) started

06259318.000 |09:56:35.902 |SdlSig |MediaConnectRequest |waitConnectRequest |MediaManager(2,100,140,15037) |MediaCoordinator(2,100,141,1) |1,200,13,32.23783^[UCCX_PUB]^CC_13170009234 |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] Party1: MR=0 CI=46062634 audioCapCount=3 region=Lightbound DC xferMode=16 mrid=0 audioId=0 MMCap=0x1 sipConfig: BFCPAllowed=F IXAllowed=F activeCap=0 cryptoCapCount=0 flushIns=0 dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F IFPid=(0,0,0,0) dtMedia=F honorCodec=F EOType=0 DTMF Caps(1,3,101,1,F) confID=0 connType=3 connStatus=0 mtpPre=F teleEve=0 IFCreated=F IFHandling=0 FS=0 mcNodeId=0LatentCaps=null dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F Party2: MR=0 CI=46062637 audioCapCount=2 region=ZP_UCCX xferMode=4 mrid=0 audioId=0 MMCap=0x1 sipConfig: BFCPAllowed=F IXAllowed=F activeCap=0 cryptoCapCount=0 flushIns=0 dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F IFPid=(0,0,0,0) dtMedia=F honorCodec=F EOType=0 DTMF Caps(1,1,0,1,F) confID=0 connType=3 connStatus=0 mtpPre=F teleEve=0 IFCreated=F IFHandling=0 FS=0 mcNodeId=0LatentCaps=null dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F reConnType=0 videoCall=F AllowedCallType=0x0 mtpChanged=F precLvl=5 resCap=0 party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 sideBAns= T
06259318.001 |09:56:35.902 |AppInfo |SIG-MediaManager-(15037)::wait_MediaConnectRequest, CI(46062634,46062637), capCount(3,2), mcNodeId(0,0), xferMode(16,4), reConnectType(0), mrid (0, 0) IFCreated(0 0) proIns(0 0), AC(0,0), party1DTMF(1 3 101 1 0) party2DTMF(1 1 0 1 0),reConnFlag=0, connType(3,3), IFHand(0,0),MTP(0,0),MRGL(579f39c7-3b64-41f0-a932-16d9b77709fb,15090c43-f224-e07f-37a8-4ec74e29f09d) videoCap(0 0), mmCallType(0),FS(0,0), IpAddrMode(0 0) aPid(2, 82, 3656), bPid(2, 63, 742) EOType(0 0) () honorCodec(0 0)

06259324.001 |09:56:35.903 |AppInfo |DET-MediaManager-(15037) - waitCACInfoRes_CACInfoRes- qosType=0 videoEsc=0 mNoVideoResvAttempted=1 VideoCall=0
06259324.002 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::waitCACInfoRes_CACInfoRes, rsvp(0,0), E2E RegionBwKbps[ A=64 V = 0 I = 0 ] ,deviceAcaps(0) deviceBCaps(0),noVideoResv(1), mmAllowedCallType(0x00000000)
06259324.003 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::mapCapabilitiesToMMCallType - Call is set to Audio Only - vidCall = 0)
06259324.004 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::buildMtpXcoderAllocList, savedConnectionCount=0, QosType=0
06259324.005 |09:56:35.903 |AppInfo |DET-RegionsServer::matchCapabilities-- savedOption=3, PREF_NONE, regionA=(null) regionB=(null) latentCaps(A=0, B=0) kbps=64, capACount=3, capBCount=2
06259324.006 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::checkAudioPassThru, param(bPostMTPAllocation=0,chkTrp=1), capCount(3,2), mtpPT=1, aPT=1
06259324.007 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::preCheckCapabilities, region1=Lightbound DC, region2=ZP_UCCX, Pty1 capCount=3 (Cap,ptime)= (4,20) (11,20) (12,20), Pty2 capCount=2 (Cap,ptime)= (2,30) (4,30)
06259324.008 |09:56:35.903 |AppInfo |DET-RegionsServer::matchCapabilities-- savedOption=0, PREF_NONE, regionA=(null) regionB=(null) latentCaps(A=0, B=0) kbps=64, capACount=3, capBCount=2
06259324.009 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::prepareInitialConnectionList, Party1CapCount=3 Party2CapCount=2 XcoderRequired=0 xcodingSide=0 allowMTP=0
06259324.010 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::AllocateXcoderandMTPWithZeroSavedConnection
06259324.011 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::isMTPNeededForDTMF, isMTPNeeded for DTMF inection from OOB to 2833 party1MTPNeed=0 party1MTPNeed=0 mtpinsertionReason=0
06259324.012 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::isMTPNeededForDTMFInjectionFromOOBTo2833 - MTPInsertionReason=0 DTMFSide=0 Party1XferMode=16 Party2XferMode=4 Party 1[DTMFConfig=1 DTMFMethod=3 wantDTMFReception=1 DTMFReception=0 MTPNeedForDTMFInject=0] Party 2[DTMFConfig=1 DTMFMethod=1 wantDTMFReception=1 DTMFReception=0 MTPNeedForDTMFInject=0]
06259324.013 |09:56:35.903 |AppInfo |!!ERROR!! -MediaManager-(15037)::isMTPNeededForDTMFInjectionFromOOBTo2833 DTMFMTPSide=0, MTPInsertReason=0
06259324.014 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::isMTPNeededForDTMF, after all MTP determinationMTPSide=0 mtpinsertionReason=0
06259324.015 |09:56:35.903 |AppInfo |DET-MediaManager-(15037) - isIpv6CapableMTPNeeded(0) ipAddrMode(0 0) mtpside(0)
06259324.016 |09:56:35.903 |AppInfo |SIG-MediaManager-(15037)::handleMediaConnectRequest, connCount=0
06259324.017 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::handleMediaConnectRequest, video(0), EOType(0, 0)
06259324.018 |09:56:35.903 |Created | | |MediaExchange(2,100,145,15054) |MediaManager(2,100,140,15037) | |NumOfCurrentInstances: 446

06259325.000 |09:56:35.903 |SdlSig |MediaConnectRequest |waitMediaConnectRequest |MediaExchange(2,100,145,15054) |MediaManager(2,100,140,15037) |1,200,13,32.23783^[UCCX_PUB]^CC_13170009234 |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] Party1: MR=0 CI=46062634 audioCapCount=3 region=Lightbound DC xferMode=16 mrid=0 audioId=0 MMCap=0x1 sipConfig: BFCPAllowed=F IXAllowed=F activeCap=0 cryptoCapCount=0 flushIns=0 dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F IFPid=(0,0,0,0) dtMedia=F honorCodec=F EOType=0 DTMF Caps(1,3,101,1,F) confID=0 connType=3 connStatus=0 mtpPre=F teleEve=0 IFCreated=F IFHandling=0 FS=0 mcNodeId=0LatentCaps=null dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F Party2: MR=0 CI=46062637 audioCapCount=2 region=ZP_UCCX xferMode=4 mrid=0 audioId=0 MMCap=0x1 sipConfig: BFCPAllowed=F IXAllowed=F activeCap=0 cryptoCapCount=0 flushIns=0 dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F IFPid=(0,0,0,0) dtMedia=F honorCodec=F EOType=0 DTMF Caps(1,1,0,1,F) confID=0 connType=3 connStatus=0 mtpPre=F teleEve=0 IFCreated=F IFHandling=0 FS=0 mcNodeId=0LatentCaps=null dtm.mode=0 dtm.CI=0 dtm.MTPForDTMF=F reConnType=0 videoCall=F AllowedCallType=0x1 mtpChanged=F precLvl=5 resCap=0 party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 sideBAns= T
06259325.001 |09:56:35.903 |AppInfo |DET-MediaExchange-(15054)::wait_MediaConnectRequest, party1(CI=46062634, MXIFHandling=0, MediaReq=0,xferMode=16),party2(CI=46062637, MXIFHandling=0,xferMode=4), farEnd(XferMode=0,AC=0,T38=0,FS=0, mediaReq=0), PT(2,2),connType(3,3), farendIpAddrMode=0
06259325.002 |09:56:35.903 |AppInfo |DET-MediaExchange-(15054)::addPartyAandPartyB, party1:xferMode=16, party2:xferMode=4, ORIGINATOR_MEDIAMANAGER
06259325.003 |09:56:35.903 |AppInfo |DET-MediaExchange-(15054)::addPartyAandPartyB, audioIdx(1), video(0), partyA(0), earlyOfferE2E=0 earlyOfferType(0:0)
06259325.004 |09:56:35.903 |AppInfo |DET-MediaExchange-(15054)::setEOOpaqueMediaInfoForInterface, peerEarlyOfferType(0), farEndEarlyOfferType(0), h323EarlyOfferInfo(0)
06259325.005 |09:56:35.903 |AppInfo |DET-MediaExchange-(15054)::setEOOpaqueMediaInfoForInterface, peerEarlyOfferType(0), farEndEarlyOfferType(0), h323EarlyOfferInfo(0)
06259325.006 |09:56:35.903 |AppInfo |DET-MediaExchange-(15054)::setRegionAndHonorIncomingCodecPrefForInterface, Party1: myRegion(Lightbound DC), peerRegion(ZP_UCCX), farEndRegion(), myHonorIncomingCodecPref(0), peerHonorIncomingCodecPref(0), farEndHonorIncomingCodecPref(0) Party2: myRegion(ZP_UCCX), peerRegion(Lightbound DC), farEndRegion(), myHonorIncomingCodecPref(0), peerHonorIncomingCodecPref(0), farEndHonorIncomingCodecPref(0)
06259325.007 |09:56:35.903 |AppInfo |DET-MediaExchange-(15054)::addPartyAandPartyB, videoCall(0), normalStart(0), HOP RegionBwKbps[ A=64 V = 0 I = 0 ] , E2E RegionBwKbps[ A=64 V = 0 I = 0 ] , party1VidCapable(0), party2VidCapable(0) 
06259325.008 |09:56:35.903 |AppInfo |DET-SIPInterface-(0)- CI=46062634 mrId=0 PartySide=65 HOP RegionBwKbps[ A=64 V = 0 I = 0 ] E2E RegionBwKbps[ A=64 V = 0 I = 0 ] vid=0 AllowedCallType=0x00000001 MCast=0 port=0 IpAddrMode(my=0 peer=0 farEnd=0) XferMode(peer=4 farEnd=0) mediaReq=0 farEndMedReq=0 PassThru(A=2 V=2) Qos(0,1) vidPref(0) isPartyA(0) otherAgentPorts=0 FSInfo=0
06259325.009 |09:56:35.903 |Created | | |SIPInterface(2,100,76,4109) |MediaExchange(2,100,145,15054) | |NumOfCurrentInstances: 136
06259325.010 |09:56:35.903 |AppInfo |DET-MediaExchange-(15054)::addPartyAandPartyB, party1iport([CUBE_IP] 51066),party2ipport(0.0.0.0 0)
06259325.011 |09:56:35.903 |AppInfo |DET-kirra-ipv6 AgenaInterfaceBase-(0)::initializeMemberData mNegotiatedIPAddrType = 0 
06259325.012 |09:56:35.903 |AppInfo |DET-AgenaInterface-created by MX(15054)::CI=46062637 allow2833(1) audioPartyId=0, mrid=0, connType(3 3 3) IPAddrMode(0 0 0) isMidMTP(0) NegotiatedIpAddrType(0) earlyOffer=0 callPrecLvl=5 MyDTMF(1 1) renegEOMed(0) E2E RegionBwKbps[ A=64 V = 0 I = 0 ] HOP RegionBwKbps[ A=64 V = 0 I = 0 ] 
06259325.013 |09:56:35.903 |Created | | |AgenaInterface(2,100,244,9534) |MediaExchange(2,100,145,15054) | |NumOfCurrentInstances: 442

06259326.000 |09:56:35.903 |SdlSig |MXInterfaceCreated |waitInterfacesCreated |MediaExchange(2,100,145,15054) |SIPInterface(2,100,76,4109) |1,200,13,32.23783^[UCCX_PUB]^CC_13170009234 |[R:N-H:0,N:3,L:0,V:0,Z:0,D:0] 
06259327.000 |09:56:35.903 |SdlSig |SIPBeginMedia |inCall_delivered |SIPCdpc(2,100,82,3656) |SIPInterface(2,100,76,4109) |1,200,13,32.23783^[UCCX_PUB]^CC_13170009234 |[R:N-H:0,N:2,L:0,V:0,Z:0,D:0] myId=-313956984 PeerDTMFConfig=1 PeerDTMFMethod=1 PeerDTMFRfc2833PT=0 PeerDTMFWantDTMF=1 PeerDTMFProvideOOB=F VideoPref=F AllowMultiCodecsInAnswer=F Tandem=F renego=F] nAudio=0 ~nVideo=0 ~nApp=0 ~nT38Fax=0 ^nBFCPApp=0 ^nIXApp=0 DTMFMethod=0 DTMFConfig=1 RFC2833PT=0 wantDTMF=1 provideOOB=F keepAudiomLineForT38=F FCOffer=0 transID=0 mANATAddrPref=3Ip_Invalid negIpAddrType=2V4V6 MTPAllocated=0
06259327.001 |09:56:35.903 |AppInfo |SIPCdpc(3656) - handleSDPOfferInd: (SDP Audio) bytes=925

06259368.001 |09:56:35.904 |AppInfo |SIPD(11) - getKeyBasedOnCiAndBranch: AddressingElement branch is 0 and ci is 46062634 mapKey is 46062634
06259368.002 |09:56:35.904 |AppInfo |SIPD(11) - getCdpcPid: found Cdpc Pid (2,100,82,3656) for mapKey 46062634
06259369.000 |09:56:35.904 |SdlSig |SIPMediaToUpdateCc |tcc_call_active7 |Cdcc(2,100,219,21893) |MatrixControl(2,100,142,22054) |1,200,13,32.23783^[UCCX_PUB]^CC_13170009234 |[R:N-H:0,N:4,L:0,V:0,Z:0,D:0] flushIns=0 updateType=2 secureStatus=1 updatePartyCI=46062634
06259369.001 |09:56:35.904 |AppInfo |Cdcc - (0021893) - dumpSecureStatus - sideA=(cap=1,1, media=0,0, feature=0,0), sideB=(cap=1,1 media=0,0, feature=0,0)
06259369.002 |09:56:35.904 |AppInfo |Cdcc - (0021893) - dumpSecureStatus - sideA=(cap=1,1, media=0,0, feature=0,0), sideB=(cap=1,1 media=0,0, feature=0,0)
06259369.003 |09:56:35.904 |AppInfo |Cdcc - (0021893)- getSecureStatusTypeGivenSide - CFBCtrlSecIcon=0, notifyDeviceType=8, SecureStatus=0, deviceName=SIP-TW-LB-CUBE
06259369.004 |09:56:35.904 |AppInfo |Cdcc - (0021893) - dumpSecureStatus - sideA=(cap=1,1, media=0,0, feature=0,0), sideB=(cap=1,1 media=0,0, feature=0,0)
06259369.005 |09:56:35.904 |AppInfo |Cdcc - (0021893)- getSecureStatusTypeGivenSide - CFBCtrlSecIcon=0, notifyDeviceType=4, SecureStatus=0, deviceName=CC_13170009234
06259369.006 |09:56:35.904 |AppInfo |Cdcc - (0021893) - SIPMediaToUpdateCc - update secure capability on side 0 = (1,1)

06259413.000 |09:56:35.908 |SdlSig |SIPSubscribeReq |wait |SIPHandler(2,100,79,1) |Subscriber(2,100,61,56) |1,200,13,32.23784^[UCCX_PUB]^CC_13170009234 |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0] ccbID=31360 --TransType=2 --TransSecurity=0 PeerAddr=[CUBE_IP]:51066 scbId=31361 addrList: 
06259413.001 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/sipSPIAddContextToTable: Added context(0xd42d998) with key=[24564] to table
06259413.002 |09:56:35.908 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=31361/ccsip_platform_init_scb: scb mgmt added 0xd42d998 (context_id=24564)
06259413.003 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/sipSPICreateSubscribeKey: Generated Subscribe Key : DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
06259413.004 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0xd42d998/sipSPIPutSCBInClientTable: Inserting SCB with key DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634 into ClientTable
06259413.005 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0xd42d998/ccsip_new_scb: Created new scb: 0xd42d998 with id: 31361
06259413.006 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 (SIP_APPLICATION_SUBSCRIBE_NOTIFY_MSG), for event 205 (UNDEFINED)
06259413.007 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_CC_SUBSCRIBE] received in State [SUBSCRIBE_STATE_IDLE]
06259413.008 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0xd42d998/sipSPIPutSCBInSubIDTable: Inserting SCB with key 31361 into SubIDTable
06259413.009 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/ccsip_new_tcb: Created TCB: 0xd3e3c08
06259413.010 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateTCBParent: TCB 0xd3e3c08's parent is 0xd42d998
06259413.011 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0xd42d998/act_idle_subscribe_event: Initiating Call-Context Subscription on CCB(0xd410c20)
06259413.012 |09:56:35.908 |AppInfo |//SIP/Stack/Transport/0x0/sipSPIUpdateTCBRequestInfo: Dialog Transaction Address [CUBE_IP],Port 5060, Port Present: TRUE, Transport
06259413.013 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0xd42d998/sipSPIPutSCBInClientTable: SCB with key DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634 already in ClientTable
06259413.014 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateTCBMethod: TCB 0xd3e3c08's method is 112
06259413.015 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateTCBClientMarker: Client TCB's Marker Updated to: z9hG4bK5f9671eeefa
06259413.016 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/ccsip_new_edb: Created new edb(0xd39cb80)
06259413.017 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateEDBEvent: EDB updated with Event Name: kpml Event ID: 
06259413.018 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0xd42d998/sipSPICreateNewEDB: Q'd EDB(0xd39cb80) on SCB(0xd42d998)
06259413.019 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/sipSPIQueTCBonEDB: Q'd TCB(0xd3e3c08) on EDB(0xd39cb80)
06259413.020 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0xd410c20/sipSPITCBSendPackage: Sending Package on tcb: 0xd3e3c08 and parent: 0xd42d998, parent context: (nil)
06259413.021 |09:56:35.908 |AppInfo |//SIP/Stack/Transport/0x0xd410c20/sipSPITransportSendMessage: msg=0xd349ee8, addr=[CUBE_IP], port=5060, sentBy_port=0, is_req=1, trans
06259413.022 |09:56:35.908 |AppInfo |//SIP/Stack/Transport/0x0/sipInstanceGetConnectionId: Registering gcb=0xd410c20 with connection=0x10b85030 context list
06259413.023 |09:56:35.908 |AppInfo |//SIP/Stack/Transport/0x0xd410c20/sipTransportLogicSendMsg: Set to send the msg=0xd349ee8
06259413.024 |09:56:35.908 |AppInfo |//SIP/Stack/Transport/0x0xd410c20/sipTransportPostSendMessage: Posting send for msg=0xd349ee8, addr=[CUBE_IP], port=5060, connId=5060 for 
06259413.025 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/sipSPIKickoffTcbReTxTimer: Kicking off ReTx Timer for Client TCB (0xd3e3c08) with 6 retries and 500 millis
06259413.026 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/ccsip_new_tcb_timer_context: Created timer context(0xd38d7b8)
06259413.027 |09:56:35.908 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer_tcb: timerContext=0xd38d7b8 type=SIP_TIMER_CLIENT_TCB value=500 retries=6
06259413.028 |09:56:35.908 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=0/sip_start_timer_tcb: timerContext=0xd38d7b8 type=SIP_TIMER_CLIENT_TCB value=500 retries=6
06259413.029 |09:56:35.908 |AppInfo |//SIP/Stack/Info/0x0/act_idle_continue_subscribe_event: Changing from State: SUBSCRIBE_STATE_IDLE to state SUBSCRIBE_STATE_ACTIVE

06259414.000 |09:56:35.908 |SdlSig |SIPSPISignal |wait |SIPUdp(2,100,70,1) |SIPHandler(2,100,79,1) |1,200,13,32.23784^[UCCX_PUB]^CC_13170009234 |*TraceFlagOverrode
06259414.001 |09:56:35.908 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[66560,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP [CUBE_IP]:5060;branch=z9hG4bK11C191B4
From: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
To: <sip:[CALLED_PARTY]@[CUCM_SUB]>;tag=31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
Date: Tue, 15 Dec 2015 14:56:35 GMT
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
CSeq: 101 INVITE
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
Allow-Events: presence, kpml
Supported: replaces
Server: Cisco-CUCM10.5
Supported: X-cisco-srtp-fallback
Supported: Geolocation
Session-Expires: 7200;refresher=uas
Require: timer
P-Asserted-Identity: <sip:+13170009234@[CUCM_SUB]>
Remote-Party-ID: <sip:+13170009234@[CUCM_SUB]>;party=called;screen=yes;privacy=off
Contact: <sip:[CALLED_PARTY]@[CUCM_SUB]:5060>
Content-Type: application/sdp
Content-Length: 185
v=0
o=CiscoSystemsCCM-SIP 31360 1 IN IP4 [CUCM_SUB]
s=SIP Call
c=IN IP4 [UCCX_PUB]
b=TIAS:64000
b=CT:64
b=AS:64
t=0 0
m=audio 25622 RTP/AVP 0
a=ptime:20
a=rtpmap:0 PCMU/8000

06259415.000 |09:56:35.908 |SdlSig |SIPSPISignal |wait |SIPUdp(2,100,70,1) |SIPHandler(2,100,79,1) |1,200,13,32.23784^[UCCX_PUB]^CC_13170009234 |*TraceFlagOverrode
06259415.001 |09:56:35.908 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[66561,NET]
SUBSCRIBE sip:[CALLING_PARTY]@[CUBE_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUCM_SUB]:5060;branch=z9hG4bK5f9671eeefa
From: <sip:[CALLED_PARTY]@[CUCM_SUB]>;tag=31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
To: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
CSeq: 101 SUBSCRIBE
Date: Tue, 15 Dec 2015 14:56:35 GMT
User-Agent: Cisco-CUCM10.5
Event: kpml
Expires: 7200
Contact: <sip:[CUCM_SUB]:5060>
Accept: application/kpml-response+xml
Max-Forwards: 70
Content-Type: application/kpml-request+xml
Content-Length: 370
<?xml version="1.0" encoding="UTF-8" ?>
<kpml-request xmlns="urn:ietf:params:xml:ns:kpml-request" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:ietf:params:xml:ns:kpml-request kpml-request.xsd" version="1.0">
<pattern interdigittimer="7260000" persist="persist">
 <regex tag="dtmf">[x*#ABCD]</regex>
 </pattern>
</kpml-request>

06259419.000 |09:56:35.909 |SdlSig |MediaConnectInfoInd |wait |MediaCoordinator(2,100,141,1) |MediaManager(2,100,140,15037) |2,100,14,1.41386^*^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] partyACI=46062634 partyBCI=46062637 mtpExists=F CallSecurityStatusNotAuthenticated party2MoHAnn=F AudConnStatus[partyA=BothEarAndMouth partyB=BothEarAndMouth] AUDIO [ PartyA - RecvRtpTa= ipAddrType=0 ipv4=[CUBE_IP]:30910 Codec=4 64 Kbps 20 Msec V4 : PartyB - RecvRtpTa= ipAddrType=0 ipv4=[UCCX_PUB]:25622 Codec=4 64 Kbps 20 Msec V4] No Main Video No Sec Video

06259420.000 |09:56:35.909 |SdlSig |MediaConnectInfoInd |wait |ConnectionManager(2,100,214,1) |MediaCoordinator(2,100,141,1) |2,100,14,1.41386^*^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] partyACI=46062634 partyBCI=46062637 mtpExists=F CallSecurityStatusNotAuthenticated party2MoHAnn=F AudConnStatus[partyA=BothEarAndMouth partyB=BothEarAndMouth] AUDIO [ PartyA - RecvRtpTa= ipAddrType=0 ipv4=[CUBE_IP]:30910 Codec=4 64 Kbps 20 Msec V4 : PartyB - RecvRtpTa= ipAddrType=0 ipv4=[UCCX_PUB]:25622 Codec=4 64 Kbps 20 Msec V4] No Main Video No Sec Video

06259421.000 |09:56:35.909 |SdlSig |MediaConnectInfoInd |connecting_ind |MatrixControl(2,100,142,22054) |ConnectionManager(2,100,214,1) |2,100,14,1.41386^*^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] partyACI=46062634 partyBCI=46062637 mtpExists=F CallSecurityStatusNotAuthenticated party2MoHAnn=F AudConnStatus[partyA=BothEarAndMouth partyB=BothEarAndMouth] AUDIO [ PartyA - RecvRtpTa= ipAddrType=0 ipv4=[CUBE_IP]:30910 Codec=4 64 Kbps 20 Msec V4 : PartyB - RecvRtpTa= ipAddrType=0 ipv4=[UCCX_PUB]:25622 Codec=4 64 Kbps 20 Msec V4] No Main Video No Sec Video

06259422.000 |09:56:35.909 |SdlSig |MediaConnectInfoInd |tcc_call_active7 |Cdcc(2,100,219,21893) |MatrixControl(2,100,142,22054) |2,100,14,1.41386^*^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] partyACI=46062634 partyBCI=46062637 mtpExists=F CallSecurityStatusNotAuthenticated party2MoHAnn=F AudConnStatus[partyA=BothEarAndMouth partyB=BothEarAndMouth] AUDIO [ PartyA - RecvRtpTa= ipAddrType=0 ipv4=[CUBE_IP]:30910 Codec=4 64 Kbps 20 Msec V4 : PartyB - RecvRtpTa= ipAddrType=0 ipv4=[UCCX_PUB]:25622 Codec=4 64 Kbps 20 Msec V4] No Main Video No Sec Video

06259432.001 |09:56:35.910 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 449 from [CUBE_IP]:[51066]:
[66562,NET]
ACK sip:[CALLED_PARTY]@[CUCM_SUB]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUBE_IP]:5060;branch=z9hG4bK11C1AAC6
From: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
To: <sip:[CALLED_PARTY]@[CUCM_SUB]>;tag=31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
Date: Tue, 15 Dec 2015 14:56:35 GMT
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
Max-Forwards: 70
CSeq: 101 ACK
Allow-Events: kpml, telephone-event
Content-Length: 0

06259433.000 |09:56:35.910 |SdlSig |SdlDataInd |wait |SIPUdp(2,100,70,1) |SdlUDPConnection(2,100,10,1) |2,100,10,1.7598^[CUBE_IP]^* |*TraceFlagOverrode
06259433.001 |09:56:35.910 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 914 from [CUBE_IP]:[51066]:
[66563,NET]
SUBSCRIBE sip:[CALLED_PARTY]@[CUCM_SUB]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUBE_IP]:5060;branch=z9hG4bK11C1B225A
From: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
To: <sip:[CALLED_PARTY]@[CUCM_SUB]>;tag=31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
CSeq: 102 SUBSCRIBE
Max-Forwards: 70
Date: Tue, 15 Dec 2015 14:56:35 GMT
User-Agent: Cisco-SIPGateway/IOS-15.4.3.M3
Event: kpml
Expires: 7200
Contact: <sip:[CALLING_PARTY]@[CUBE_IP]:5060>
Content-Type: application/kpml-request+xml
Content-Length: 327
<?xml version="1.0" encoding="UTF-8"?><kpml-request xmlns="urn:ietf:params:xml:ns:kpml-request" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="urn:ietf:params:xml:ns:kpml-request kpml-request.xsd" version="1.0"><pattern persist="persist"><regex tag="dtmf">[x*#ABCD]</regex></pattern></kpml-request>

06259434.000 |09:56:35.910 |SdlSig |SdlDataInd |wait |SIPUdp(2,100,70,1) |SdlUDPConnection(2,100,10,1) |2,100,10,1.7599^[CUBE_IP]^* |*TraceFlagOverrode
06259434.001 |09:56:35.910 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 433 from [CUBE_IP]:[51066]:
[66564,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP [CUCM_SUB]:5060;branch=z9hG4bK5f9671eeefa
From: <sip:[CALLED_PARTY]@[CUCM_SUB]>;tag=31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
To: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
Date: Tue, 15 Dec 2015 14:56:35 GMT
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
CSeq: 101 SUBSCRIBE
Content-Length: 0
Contact: <sip:[CALLING_PARTY]@[CUBE_IP]:5060>
Expires: 3600

06259442.001 |09:56:35.910 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 537 from [CUBE_IP]:[51066]:
[66565,NET]
NOTIFY sip:[CUCM_SUB]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUBE_IP]:5060;branch=z9hG4bK11C1C171E
From: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
To: <sip:[CALLED_PARTY]@[CUCM_SUB]>;tag=31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
CSeq: 103 NOTIFY
Max-Forwards: 70
Date: Tue, 15 Dec 2015 14:56:35 GMT
User-Agent: Cisco-SIPGateway/IOS-15.4.3.M3
Event: kpml
Subscription-State: active
Contact: <sip:[CALLING_PARTY]@[CUBE_IP]:5060>
Content-Length: 0

06259443.000 |09:56:35.910 |SdlSig |SIPSubscribeInd |restart0 |SIPD(2,100,81,11) |SIPHandler(2,100,79,1) |2,100,10,1.7598^[CUBE_IP]^* |[R:N-H:0,N:1,L:0,V:0,Z:0,D:0] ccbID= 31360 --TransType=2 --TransSecurity=0 PeerAddr = [CUBE_IP]:51066
06259443.001 |09:56:35.910 |AppInfo |supportsConferenceFactoryFlow: assip=0 
06259443.002 |09:56:35.910 |AppInfo |SIPD(11) - restart0_SIPSubscribeInd: Received initial SUBSCRIBE event for kpml
06259443.003 |09:56:35.910 |AppInfo |SIPD(11) - getKeyBasedOnCiAndBranch: AddressingElement branch is 0 and ci is 46062634 mapKey is 46062634
06259443.004 |09:56:35.910 |AppInfo |SIPD(11) - getCdpcPidGivenCcbidAndCi: found Cdpc Pid (2,100,82,3656) for mapKey 46062634

06259444.000 |09:56:35.910 |SdlSig |SIPSubscribeInd |active |SIPCdpc(2,100,82,3656) |SIPD(2,100,81,11) |2,100,10,1.7598^[CUBE_IP]^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] ccbID= 31360 --TransType=2 --TransSecurity=0 PeerAddr = [CUBE_IP]:51066
06259444.001 |09:56:35.910 |AppInfo |SIPCdpc(3656) - star_SIPSubscribeInd: Received a SUBSCRIBE from an endpoint.tcbId=0x0xd5131c8, SNFPkgId=3
06259444.002 |09:56:35.910 |AppInfo |SIPCdpc(3656) - star_SIPSubscribeInd: Creating Notifier for DTMF-KPML.
06259444.003 |09:56:35.910 |AppInfo |SIPEventPkg::SIPEventPkg 0xdefd8420 scbId[31361], event name[kpml], id[]
06259444.004 |09:56:35.910 |Created | | |Notifier(2,100,124,24) |SIPD(2,100,81,11) | |NumOfCurrentInstances: 2
06259444.005 |09:56:35.910 |AppInfo |setOobScbId: mOobScbId=31361
06259444.006 |09:56:35.910 |AppInfo |SIPCdpc(3656) - star_SIPSubscribeInd: Adding Notifier(KPML) to SIPSubNotTable, snfSubId=2|0|141

06259445.000 |09:56:35.910 |SdlSig |SIPSPISignal |wait |SIPHandler(2,100,79,1) |SIPUdp(2,100,70,1) |2,100,10,1.7599^[CUBE_IP]^* |*TraceFlagOverrode
06259445.001 |09:56:35.910 |AppInfo |//SIP/Stack/Info/0x0/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 (SIP_NETWORK_MSG), for event 1 (SIPSPI_EV_NEW_MESSAGE)
06259445.002 |09:56:35.910 |AppInfo |//SIP/Stack/Transport/0x0/sipTransportProcessNWNewConnMsg: context=(nil)
06259445.003 |09:56:35.910 |AppInfo |//SIP/Stack/Transport/0x0/sipConnectionManagerProcessNewConnMsg: gConnTab=0x10b83f58, addr=[CUBE_IP], port=51066, connid=5060, transport=UDP
06259445.004 |09:56:35.910 |AppInfo |//SIP/Stack/Info/0x0/sipHolderGetConnInstance: Return existing connection for port 51066 connId 5060
06259445.005 |09:56:35.910 |AppInfo |//SIP/Stack/Info/0x0/sipSPICreateSubscribeKey: Generated Subscribe Key : DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
06259445.006 |09:56:35.910 |AppInfo |//SIP/Stack/Info/0x0/ccsip_spi_process_event: Event [SIPSPI_EV_NEW_MSG] received in State [SUBSCRIBE_STATE_ACTIVE]
06259445.007 |09:56:35.910 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer_tcb: timerContext=0xd38d7b8 type=SIP_TIMER_CLIENT_TCB value=500 retries=6
06259445.008 |09:56:35.910 |AppInfo |//SIP/Stack/Info/0x0xd3e3c08/sipSPIFreeOneTCB: Invoking sipSPIFreeOneTCB - Ref count: 3
06259445.009 |09:56:35.910 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=31361/findDevicePID: Routed to SIPD by ccbId/scbId
06259445.010 |09:56:35.910 |AppInfo |//SIP/Stack/Info/0x0xd42d998/sipSPIReportRequestSendStatus: ccsip_api_subscribe_result returned: SIP_SUCCESS

06259446.000 |09:56:35.910 |SdlSig |SNFSubscribeInd |init |Notifier(2,100,124,24) |SIPCdpc(2,100,82,3656) |2,100,10,1.7598^[CUBE_IP]^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] SNFSubscriptionId = 2|0|141, SNFSubscriptionMsg contents: SNFSubscriptionType = KPML , duration = 7200, routeFlag = false, authFlag = false, forwardFlag = false, cacheStateFlag = false, bulkUnSubscribeFlag = false, subscriber = , subscribee = [CALLED_PARTY], subscriberUrl = , subscribeeUrl = , subCSS = , srcPresGrpPkid = , destinationPid = (0,0,0), destinationCepn = , pretransformTagsList = , pretransformPositionalMatchList = , mApplyURIDisambiguation = false, mURIDisambiguationPolicy = 3
06259446.001 |09:56:35.910 |AppInfo |SIPEventPkg::subscribeInd exp = 7200, t = 9000
06259446.002 |09:56:35.910 |AppInfo |SIPKpmlEventPkg::notifierRouteAndAuthorize
06259446.003 |09:56:35.910 |AppInfo |SIPEventPkg::sendSIPSubResponse 200
06259446.004 |09:56:35.910 |AppInfo |SIPEventPkg::sendEmptyNotify state = 1 reason = 0

06259447.000 |09:56:35.910 |SdlSig |SIPSubscribeResult |restart0 |SIPD(2,100,81,11) |SIPHandler(2,100,79,1) |2,100,10,1.7599^[CUBE_IP]^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] --TransType=2 --TransSecurity=0 PeerAddr = [CUBE_IP]:51066

06259448.000 |09:56:35.910 |SdlSig |SNFSubscribeResult |active |Subscriber(2,100,61,56) |SIPD(2,100,81,11) |2,100,10,1.7599^[CUBE_IP]^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] SNFSubscriptionId = 2|0|140, ResultCode = 200 Expires = 3600
06259448.001 |09:56:35.910 |AppInfo |SIPEventPkg::subscriberSubscribeResult(200) 2|0|140 type 
06259448.002 |09:56:35.910 |AppInfo |SIPEventPkg::subscriberSubscribeResult result = 200, subDialogState = 0, exp = 3600, t = 1800

06259449.000 |09:56:35.910 |SdlSig |SIPSPISignal |wait |SIPHandler(2,100,79,1) |SIPUdp(2,100,70,1) |2,100,10,1.7600^[CUBE_IP]^* |*TraceFlagOverrode
06259449.001 |09:56:35.910 |AppInfo |//SIP/Stack/Info/0x0/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 (SIP_NETWORK_MSG), for event 1 (SIPSPI_EV_NEW_MESSAGE)
06259449.002 |09:56:35.910 |AppInfo |//SIP/Stack/Transport/0x0/sipTransportProcessNWNewConnMsg: context=(nil)
06259449.003 |09:56:35.910 |AppInfo |//SIP/Stack/Transport/0x0/sipConnectionManagerProcessNewConnMsg: gConnTab=0x10b83f58, addr=[CUBE_IP], port=51066, connid=5060, transport=UDP
06259449.004 |09:56:35.910 |AppInfo |//SIP/Stack/Info/0x0/sipHolderGetConnInstance: Return existing connection for port 51066 connId 5060
06259449.005 |09:56:35.910 |AppInfo |//SIP/Stack/Info/0x0/sipSPICreateSubscribeKey: Generated Subscribe Key : DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
06259449.006 |09:56:35.910 |AppInfo |//SIP/Stack/Info/0x0/ccsip_spi_process_event: Event [SIPSPI_EV_NEW_MSG] received in State [SUBSCRIBE_STATE_ACTIVE]
06259449.007 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0xd410c20/sipGenCheckCseq: Difference in CSEQ numbers: 1
06259449.008 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/ccsip_new_tcb: Created TCB: 0x11a51f88
06259449.009 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateTCBServerMarker: Server TCB's Marker Updated to: 103NOTIFYz9hG4bK11C1C171E
06259449.010 |09:56:35.911 |AppInfo |//SIP/Stack/Transport/0x0/sipSPIUpdateTCBResponseInfo: Dialog Transaction Address [CUBE_IP],Port 5060, Transport 1, SentBy Port 
06259449.011 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateTCBParent: TCB 0x11a51f88's parent is 0xd42d998
06259449.012 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateTCBLastRequest: TCB(0x11a51f88) has claimed possesion of lastReq (0xdee5d2f0)
06259449.013 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIQueTCBonEDB: Q'd TCB(0x11a51f88) on EDB(0xd39cb80)
06259449.014 |09:56:35.911 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=31361/findDevicePID: Routed to SIPD by ccbId/scbId
06259449.015 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0xd42d998/sipSPIHandleNotifyOnExistingDialog: ccsip_api_notify_ind returned: SIP_SUCCESS

06259450.000 |09:56:35.911 |SdlSig |SIPNotifyInd |restart0 |SIPD(2,100,81,11) |SIPHandler(2,100,79,1) |2,100,10,1.7600^[CUBE_IP]^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] scbID=31361 --TransType=2 --TransSecurity=0 PeerAddr = [CUBE_IP]:51066
06259451.000 |09:56:35.911 |SdlSig |SNFNotifyInd |active |Subscriber(2,100,61,56) |SIPD(2,100,81,11) |2,100,10,1.7600^[CUBE_IP]^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] SNFSubscriptionId = 2|0|140, SNFNotifyMsg: state = 1, reason = 0, retryAfter = -1, subscriptionType = KPML , content = no content
, mProtocolData is not null
06259451.001 |09:56:35.911 |AppInfo |SIPKpmlEventPkg::subscriberNotifyInd tcbIndex = 0X11A51F88 state = 1 reason = 0
06259451.002 |09:56:35.911 |AppInfo |SIPEventPkg::sendSIPNotResponse 200
06259451.003 |09:56:35.911 |AppInfo |SIPKpmlDtmfEventPkg::forwardNotifiedDigits ENTER
06259451.004 |09:56:35.911 |AppInfo |SIPKpmlDtmfEventPkg::forwardNotifiedDigits NULL body

06259452.000 |09:56:35.911 |SdlSig |SIPSubscribeResp |wait |SIPHandler(2,100,79,1) |Notifier(2,100,124,24) |2,100,10,1.7598^[CUBE_IP]^* |[T:N-H:0,N:2,L:0,V:0,Z:0,D:0] scbId= 31361 --TransType=2 --TransSecurity=0 PeerAddr= [CUBE_IP]:51066 respCode= 200
06259452.001 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 (SIP_APPLICATION_SUBSCRIBE_NOTIFY_MSG), for event 203 (UNDEFINED)
06259452.002 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_CC_SUBSCRIBE_RESP] received in State [SUBSCRIBE_STATE_ACTIVE]
06259452.003 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateTCBMethod: TCB 0xd5131c8's method is 112
06259452.004 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0xd410c20/sipSPITCBSendPackage: Sending Package on tcb: 0xd5131c8 and parent: 0xd42d998, parent context: 0xd3e3c08
06259452.005 |09:56:35.911 |AppInfo |//SIP/Stack/Transport/0x0xd410c20/sipSPITransportSendMessage: msg=0x11a62978, addr=[CUBE_IP], port=5060, sentBy_port=5060, is_req=0, trans
06259452.006 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0xd3e3c08/_sipSPIFreeOneTCB: Invoking SIP TCB destructor
06259452.007 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0xd3e3c08/_sipSPIFreeOneTCB: Invoking nullify package
06259452.008 |09:56:35.911 |AppInfo |//SIP/Stack/Transport/0x0xd410c20/sipTransportPostSendMessage: Posting send for msg=0x11a62978, addr=[CUBE_IP], port=5060, connId=0 for 
06259452.009 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIKickOffTcbDieTimer: Kicking off Die Timer for Server TCB (0xd5131c8)
06259452.010 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/ccsip_new_tcb_timer_context: Created timer context(0xd401b10)
06259452.011 |09:56:35.911 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer_tcb: timerContext=0xd401b10 type=SIP_TIMER_SERVER_TCB value=32000 retries=0
06259452.012 |09:56:35.911 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=0/sip_start_timer_tcb: timerContext=0xd401b10 type=SIP_TIMER_SERVER_TCB value=32000 retries=0

06259453.000 |09:56:35.911 |SdlSig |SIPSPISignal |wait |SIPUdp(2,100,70,1) |SIPHandler(2,100,79,1) |2,100,10,1.7598^[CUBE_IP]^* |*TraceFlagOverrode
06259453.001 |09:56:35.911 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[66566,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP [CUBE_IP]:5060;branch=z9hG4bK11C1B225A
From: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
To: <sip:[CALLED_PARTY]@[CUCM_SUB]>;tag=31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
Date: Tue, 15 Dec 2015 14:56:35 GMT
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
CSeq: 102 SUBSCRIBE
Server: Cisco-CUCM10.5
Contact: <sip:[CUCM_SUB]:5060>
Expires: 7200
Content-Length: 0

06259454.000 |09:56:35.911 |SdlSig |SIPNotifyReq |wait |SIPHandler(2,100,79,1) |Notifier(2,100,124,24) |2,100,10,1.7598^[CUBE_IP]^* |[T:N-H:0,N:1,L:0,V:0,Z:0,D:0] --TransType=2 --TransSecurity=0 PeerAddr = [CUBE_IP]:51066 addrList: 
06259454.001 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 (SIP_APPLICATION_SUBSCRIBE_NOTIFY_MSG), for event 204 (UNDEFINED)
06259454.002 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_CC_NOTIFY] received in State [SUBSCRIBE_STATE_ACTIVE]
06259454.003 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/ccsip_new_tcb: Created TCB: 0xd3e3c08
06259454.004 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateTCBParent: TCB 0xd3e3c08's parent is 0xd42d998
06259454.005 |09:56:35.911 |AppInfo |//SIP/Stack/Transport/0x0/sipSPIUpdateTCBRequestInfo: Dialog Transaction Address [CUBE_IP],Port 5060, Port Present: TRUE, Transport
06259454.006 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateTCBMethod: TCB 0xd3e3c08's method is 111
06259454.007 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateTCBClientMarker: Client TCB's Marker Updated to: z9hG4bK5f97776b9343
06259454.008 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIQueTCBonEDB: Q'd TCB(0xd3e3c08) on EDB(0xd39cb80)
06259454.009 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0xd410c20/sipSPITCBSendPackage: Sending Package on tcb: 0xd3e3c08 and parent: 0xd42d998, parent context: 0xd5131c8
06259454.010 |09:56:35.911 |AppInfo |//SIP/Stack/Transport/0x0xd410c20/sipSPITransportSendMessage: msg=0xd415798, addr=[CUBE_IP], port=5060, sentBy_port=0, is_req=1, trans
06259454.011 |09:56:35.911 |AppInfo |//SIP/Stack/Transport/0x0/sipInstanceGetConnectionId: gcb=0xd410c20 is already on connection=0x10b85030 context_list
06259454.012 |09:56:35.911 |AppInfo |//SIP/Stack/Transport/0x0xd410c20/sipTransportLogicSendMsg: Set to send the msg=0xd415798
06259454.013 |09:56:35.911 |AppInfo |//SIP/Stack/Transport/0x0xd410c20/sipTransportPostSendMessage: Posting send for msg=0xd415798, addr=[CUBE_IP], port=5060, connId=5060 for 
06259454.014 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIKickoffTcbReTxTimer: Kicking off ReTx Timer for Client TCB (0xd3e3c08) with 10 retries and 500 millis
06259454.015 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/ccsip_new_tcb_timer_context: Created timer context(0xd5368a0)
06259454.016 |09:56:35.911 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer_tcb: timerContext=0xd5368a0 type=SIP_TIMER_CLIENT_TCB value=500 retries=10
06259454.017 |09:56:35.911 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=0/sip_start_timer_tcb: timerContext=0xd5368a0 type=SIP_TIMER_CLIENT_TCB value=500 retries=10

06259455.000 |09:56:35.911 |SdlSig |SIPSPISignal |wait |SIPUdp(2,100,70,1) |SIPHandler(2,100,79,1) |2,100,10,1.7598^[CUBE_IP]^* |*TraceFlagOverrode
06259455.001 |09:56:35.911 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[66567,NET]
NOTIFY sip:[CALLING_PARTY]@[CUBE_IP]:5060 SIP/2.0
Via: SIP/2.0/UDP [CUCM_SUB]:5060;branch=z9hG4bK5f97776b9343
From: <sip:[CALLED_PARTY]@[CUCM_SUB]>;tag=31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
To: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
CSeq: 102 NOTIFY
Max-Forwards: 70
Date: Tue, 15 Dec 2015 14:56:35 GMT
User-Agent: Cisco-CUCM10.5
Event: kpml
Subscription-State: active;expires=7200
Contact: <sip:[CUCM_SUB]:5060>
Content-Length: 0

06259456.000 |09:56:35.911 |SdlSig |SIPNotifyResp |wait |SIPHandler(2,100,79,1) |Subscriber(2,100,61,56) |2,100,10,1.7600^[CUBE_IP]^* |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0] scbID=31361 --TransType=2 --TransSecurity=0 PeerAddr= [CUBE_IP]:51066 respCode=200
06259456.001 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 7 (SIP_APPLICATION_SUBSCRIBE_NOTIFY_MSG), for event 206 (UNDEFINED)
06259456.002 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_CC_NOTIFY_RESP] received in State [SUBSCRIBE_STATE_ACTIVE]
06259456.003 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIUpdateTCBMethod: TCB 0x11a51f88's method is 111
06259456.004 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0xd410c20/sipSPITCBSendPackage: Sending Package on tcb: 0x11a51f88 and parent: 0xd42d998, parent context: 0xd3e3c08
06259456.005 |09:56:35.911 |AppInfo |//SIP/Stack/Transport/0x0xd410c20/sipSPITransportSendMessage: msg=0xd416bd8, addr=[CUBE_IP], port=5060, sentBy_port=5060, is_req=0, trans
06259456.006 |09:56:35.911 |AppInfo |//SIP/Stack/Transport/0x0xd410c20/sipTransportPostSendMessage: Posting send for msg=0xd416bd8, addr=[CUBE_IP], port=5060, connId=0 for 
06259456.007 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/sipSPIKickOffTcbDieTimer: Kicking off Die Timer for Server TCB (0x11a51f88)
06259456.008 |09:56:35.911 |AppInfo |//SIP/Stack/Info/0x0/ccsip_new_tcb_timer_context: Created timer context(0x10b9c980)
06259456.009 |09:56:35.911 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer_tcb: timerContext=0x10b9c980 type=SIP_TIMER_SERVER_TCB value=32000 retries=0
06259456.010 |09:56:35.911 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=0/sip_start_timer_tcb: timerContext=0x10b9c980 type=SIP_TIMER_SERVER_TCB value=32000 retries=0

06259457.000 |09:56:35.911 |SdlSig |SIPSPISignal |wait |SIPUdp(2,100,70,1) |SIPHandler(2,100,79,1) |2,100,10,1.7600^[CUBE_IP]^* |*TraceFlagOverrode
06259457.001 |09:56:35.911 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to [CUBE_IP]:[5060]:
[66568,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP [CUBE_IP]:5060;branch=z9hG4bK11C1C171E
From: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
To: <sip:[CALLED_PARTY]@[CUCM_SUB]>;tag=31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
Date: Tue, 15 Dec 2015 14:56:35 GMT
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
CSeq: 103 NOTIFY
Server: Cisco-CUCM10.5
Content-Length: 0

06259458.000 |09:56:35.912 |SdlSig |SdlDataInd |wait |SIPUdp(2,100,70,1) |SdlUDPConnection(2,100,10,1) |2,100,10,1.7601^[CUBE_IP]^* |*TraceFlagOverrode
06259458.001 |09:56:35.912 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 372 from [CUBE_IP]:[51066]:
[66569,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP [CUCM_SUB]:5060;branch=z9hG4bK5f97776b9343
From: <sip:[CALLED_PARTY]@[CUCM_SUB]>;tag=31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
To: "BUTCHER ERIC " <sip:[CALLING_PARTY]@[CUBE_IP]>;tag=3164DA1C-1A5B
Date: Tue, 15 Dec 2015 14:56:35 GMT
Call-ID: DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]
CSeq: 102 NOTIFY
Content-Length: 0

06259459.000 |09:56:35.912 |SdlSig |SIPSPISignal |wait |SIPHandler(2,100,79,1) |SIPUdp(2,100,70,1) |2,100,10,1.7601^[CUBE_IP]^* |*TraceFlagOverrode
06259459.001 |09:56:35.912 |AppInfo |//SIP/Stack/Info/0x0/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 (SIP_NETWORK_MSG), for event 1 (SIPSPI_EV_NEW_MESSAGE)
06259459.002 |09:56:35.912 |AppInfo |//SIP/Stack/Transport/0x0/sipTransportProcessNWNewConnMsg: context=(nil)
06259459.003 |09:56:35.912 |AppInfo |//SIP/Stack/Transport/0x0/sipConnectionManagerProcessNewConnMsg: gConnTab=0x10b83f58, addr=[CUBE_IP], port=51066, connid=5060, transport=UDP
06259459.004 |09:56:35.912 |AppInfo |//SIP/Stack/Info/0x0/sipHolderGetConnInstance: Return existing connection for port 51066 connId 5060
06259459.005 |09:56:35.912 |AppInfo |//SIP/Stack/Info/0x0/sipSPICreateSubscribeKey: Generated Subscribe Key : DF2A884E-A27211E5-8214BBF3-4A589AAC@[CUBE_IP]31360~99cf0eaf-8a4f-4b68-b666-f468533531f5-46062634
06259459.006 |09:56:35.912 |AppInfo |//SIP/Stack/Info/0x0/ccsip_spi_process_event: Event [SIPSPI_EV_NEW_MSG] received in State [SUBSCRIBE_STATE_ACTIVE]
06259459.007 |09:56:35.912 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer_tcb: timerContext=0xd5368a0 type=SIP_TIMER_CLIENT_TCB value=500 retries=10
06259459.008 |09:56:35.912 |AppInfo |//SIP/Stack/Info/0x0xd3e3c08/sipSPIFreeOneTCB: Invoking sipSPIFreeOneTCB - Ref count: 2
06259459.009 |09:56:35.912 |AppInfo |//SIP/Stack/Info/0x0xd3e3c08/_sipSPIFreeOneTCB: Invoking SIP TCB destructor
06259459.010 |09:56:35.912 |AppInfo |//SIP/Stack/Info/0x0xd3e3c08/_sipSPIFreeOneTCB: Invoking nullify package
06259459.011 |09:56:35.912 |AppInfo |//SIP/SIPHandler/ccbId=0/scbId=31361/findDevicePID: Routed to SIPD by ccbId/scbId
06259459.012 |09:56:35.912 |AppInfo |//SIP/Stack/Info/0x0xd42d998/sipSPIReportRequestSendStatus: ccsip_api_notify_result returned: SIP_SUCCESS

06259460.000 |09:56:35.912 |SdlSig |SIPNotifyResult |restart0 |SIPD(2,100,81,11) |SIPHandler(2,100,79,1) |2,100,10,1.7601^[CUBE_IP]^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] --TransType=2 --TransSecurity=0 PeerAddr = [CUBE_IP]:51066
06259460.001 |09:56:35.912 |AppInfo |SIPD(11) - processSIPNotifyResult: eventId[]

06259461.000 |09:56:35.912 |SdlSig |SNFNotifyResult |active |Notifier(2,100,124,24) |SIPD(2,100,81,11) |2,100,10,1.7601^[CUBE_IP]^* |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] SNFSubscriptionId = 2|0|141, ResultCode = 200
06259461.001 |09:56:35.912 |AppInfo |SIPEventPkg::notifierNotifyResult result = 200 termNot not sent continuing

Ayodeji Okanlawon · ‎12-15-2015

Eric,

Looks like we have our answer here.

MTPNeed=0

6259324.011 |09:56:35.903 |AppInfo |DET-MediaManager-(15037)::isMTPNeededForDTMF, isMTPNeeded for DTMF inection from OOB to 2833 party1MTPNeed=0 party1MTPNeed=0 mtpinsertionReason=0

In CUCM version 9.X and earlier this is what you see.

00028211.015 |12:59:46.338 |AppInfo |DET-MediaManager-(13)::isMTPNeededForMismatchOrConfig, MTPNeededDueToDTMFCapMismatch(2833/OOB) mtpinsertionReason=1 dtmfMTPSide=2

This is a big improvement. imagine that without this all your calls to UCCX would have been invoking MTP.

Please rate all useful posts

eric.butcher · ‎12-15-2015

Yes, for sure. The more pressing question, though, is are they officially supporting DTMF Interworking bewteen rtp-nte and sip-kpml? Because every indication I see from my call flows is that yes, they are. In which case, does a documentation defect need to be opened on this?

I'm still working on getting my smartnet straightened out for this device (not sure our Cisco Partner put it on the right contract number or maybe put it on a new separate contract that I don't have access to) to open a tac case, but I'm curious to know what your intuition would be here. It doesn't seem to be "working by defect".

Ayodeji Okanlawon · ‎12-15-2015

I can open a tac case right now and we can get to the bottom of it. Let me know if you are interested.

Please rate all useful posts

eric.butcher · ‎12-15-2015

I've got a case open now, I'll let you know what I find out.

eric.butcher · ‎12-21-2015

I’ve been in touch with the CUCM engineer and also done some research and worked with some colleagues. I acknowledge that this works and it will not need an MTP and this is known. The reason it’s not supported is we need to ensure proper delivery and there can be some behaviors that are not intended and was never designed to work this way. If it works for you reliably, you can continue to do this but keep in mind if there is a case that would require an escalation we couldn’t support you further.

I hope this answers your question.

This is the answer I got back from TAC on the apparent interworking between rtp-nte and sip-kpml.

I have yet to come across an error with this configuration working since I put it in place, and thousands of calls have gone through the CUBE. However, it is officially a working, yet unsupported configuration.

Nothing clear on why the rtp-nte to sip-notify interworking breaks after transfer yet.

Ayodeji Okanlawon · ‎12-21-2015

This is fascinating stuff!!! Cisco wont support a solution they put out there. They need to give us something more concrete than this. If this is already known to them, then they should raise a bug to that effect and at least get things cleared.

Please rate all useful posts