MGCP DTMF Relay issue, some duplicate digits

[cmdemo]

Hello community,

We are facing an issue with DTMF relay. Sometimes, digits are duplicated

Topology:

DECT ANALOG -----qgig----2921----mgcp----CUCM

GW is mgcp and DTMF is configured for OOB

We checked the traces and found the following:

Apr 10 2018 14:54:39.152 GMT+2: MGCP Packet sent to 10.245.194.104:2427--->
200 60716
X: 1
<---

Apr 10 2018 14:54:41.864 GMT+2:          s=DSP d=VoIP payload 0x65 ssrc 0x3ED24DE0 sequence 0xF5C4 timestamp 0x3ED24 DE0
Apr 10 2018 14:54:41.864 GMT+2:          Pt:101    Evt:1       Pkt:03 00 50  <Snd>>>
Apr 10 2018 14:54:41.912 GMT+2:          s=DSP d=VoIP payload 0x65 ssrc 0x3ED24DE0 sequence 0x2FA8 timestamp 0x3ED24 DE0
Apr 10 2018 14:54:41.912 GMT+2:          Pt:101    Evt:1       Pkt:03 01 E0  <Snd>>>
Apr 10 2018 14:54:41.936 GMT+2:          s=DSP d=VoIP payload 0x65 ssrc 0x3ED24DE0 sequence 0xF5C4 timestamp 0x3ED24 DE0
Apr 10 2018 14:54:41.936 GMT+2:          Pt:101    Evt:1       Pkt:83 02 80  <Snd>>>

++++DSP found digit 1 in RTP stream

Apr 10 2018 14:54:41.936 GMT+2: MGCP Packet sent to 10.245.194.104:2427--->
NTFY 683339003 S0/SU0/DS1-1/3@DID-LRAG248 MGCP 0.1
N: ca@10.245.194.104:2427
X: 3
O: D/1
<---
++++ GW sends a MGCP NTFY to inform CUCM from digit collection

Apr 10 2018 14:54:41.936 GMT+2: MGCP Packet received from 10.245.194.104:2427--->
200 683339003
<---

CUCM Ack

Apr 10 2018 14:54:41.936 GMT+2: MGCP Packet received from 10.245.194.104:2427--->
RQNT 60717 S0/SU0/DS1-1/3@DID-LRAG248 MGCP 0.1
X: 3
R: D/[0-9ABCD*#]
Q: process,loop
<---

+++CUCM Asks the GW to listen to further digits

Apr 10 2018 14:54:41.936 GMT+2: MGCP Packet sent to 10.245.194.104:2427--->
200 60717 OK
<---
=======AT this stage the GW notified the CUCM from the reception of one digit=====

but 80ms later, the digit is still in the rtp stream and is catched a second time by the DSP
Apr 10 2018 14:54:41.944 GMT+2:          s=DSP d=VoIP payload 0x65 ssrc 0x3ED24DE0 sequence 0x2FA8 timestamp 0x3ED24 DE0
Apr 10 2018 14:54:41.944 GMT+2:          Pt:101    Evt:1       Pkt:83 02 80  <Snd>>>
Apr 10 2018 14:54:41.952 GMT+2:          s=DSP d=VoIP payload 0x65 ssrc 0x3ED24DE0 sequence 0x2FA8 timestamp 0x3ED24 DE0
Apr 10 2018 14:54:41.952 GMT+2:          Pt:101    Evt:1       Pkt:83 02 80  <Snd>>>
Apr 10 2018 14:54:42.028 GMT+2: MGCP Packet sent to 10.245.194.104:2427--->

++++ GW sends a second MGCP NTFY to inform CUCM
NTFY 683339004 S0/SU0/DS1-1/1@DID-LRAG248 MGCP 0.1
N: ca@10.245.194.104:2427
X: 1
O: D/1
<---

Apr 10 2018 14:54:42.028 GMT+2: MGCP Packet received from 10.245.194.104:2427--->
200 683339004
<---

Can someone confirm that we found the root cause? If yes, what can we do to avoid this situation. I checked the DECT software and there is no parameter to reduce dtmf duration. Can we handle this on GW or CUCM? Is there some dtmf timers/settings we can tune to fix this?

Thanks for your advises and guidances.

./WM

[R0g22]

Every digit would appear 7 times in the logs for NTE. Is this intermittent or happens every time or is easily reproducible ?

[Mohammed al Baqari]

Can you debug voice ccapi all? We need to confirm if the digits still being
sent from DCET or MGCP GW is having a bug.

If the digits are still being sent from DCET then nothing can be done to
fix it from MGCP point. However, if MGCP problem then we can drill further.

[cmdemo]

Hello,

Thank you for taking the time to read and help.

pr 12 2018 10:27:05.473 GMT+2:   stream[0]: callid:0x2F0, media_passthrough:0
Apr 12 2018 10:27:05.473 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_begin:
Apr 12 2018 10:27:05.473 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x3EDCCD98, Destination Mask=0x3, Destination Call Id=746,
   Source Call Id=745, Digit=2, DigitBeginFlags=0x1,
   Rtp Timestamp=0xDCD8FDE0, Rtp Expiration=0x0
Apr 12 2018 10:27:05.473 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_begin:
   Consume mask is not set. Relaying Digit 2 to dstCallId 0x2EA
Apr 12 2018 10:27:05.473 GMT+2: //745/4BE2386A8188/CCAPI/cc_relay_digit_begin_for_3way_conference:
Apr 12 2018 10:27:05.473 GMT+2: //745/4BE2386A8188/CCAPI/cc_relay_digit_begin_for_3way_conference:
   Check DTMF relay digit begin for 3way conf
Apr 12 2018 10:27:05.473 GMT+2: //747/75C7CBFD8189/CCAPI/cc_api_call_digit_end:
Apr 12 2018 10:27:05.473 GMT+2: //747/75C7CBFD8189/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x3EDCCD98, Destination Mask=0x1, Destination Call Id=748,
   Source Call Id=747, Digit=2, Duration=97,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
Apr 12 2018 10:27:05.473 GMT+2: //747/75C7CBFD8189/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
Apr 12 2018 10:27:05.473 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_end:
Apr 12 2018 10:27:05.473 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x3EDCCD98, Destination Mask=0x3, Destination Call Id=746,
   Source Call Id=745, Digit=2, Duration=117,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
Apr 12 2018 10:27:05.473 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
Apr 12 2018 10:27:05.473 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_end:
   Consume mask is not set. Relaying Digit 2 to dstCallId 0x2EA
Apr 12 2018 10:27:05.473 GMT+2: //745/4BE2386A8188/CCAPI/cc_relay_digit_end_for_3way_conference:
Apr 12 2018 10:27:05.473 GMT+2: //745/4BE2386A8188/CCAPI/cc_relay_digit_end_for_3way_conference:
   Check DTMF relay digit end for 3way conf
Apr 12 2018 10:27:05.473 GMT+2: //743/AD9A11A78187/CCAPI/ccGetCallActiveByCallID:
Apr 12 2018 10:27:05.473 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_modify_done:
   Result=0, Interface=0x3F7D731C, Call Id=751
Apr 12 2018 10:27:05.473 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_modify_done:
Apr 12 2018 10:27:05.477 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/ccGetVoicePortsOnPlatform:
   voice platform ports 0

Apr 12 2018 10:27:05.477 GMT+2: MGCP Packet sent to 10.245.194.104:2427--->
NTFY 683349584 S0/SU0/DS1-1/3@DID-LRAG248 MGCP 0.1
N: ca@10.245.194.104:2427
X: 3
O: D/2
<---

Apr 12 2018 10:27:05.477 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/ccGetVoicePortsOnPlatform:
   voice platform ports 0

Apr 12 2018 10:27:05.477 GMT+2: MGCP Packet sent to 10.245.194.104:2427--->
NTFY 683349585 S0/SU0/DS1-1/2@DID-LRAG248 MGCP 0.1
N: ca@10.245.194.104:2427
X: 2
O: D/2
<---

Not sure to read this the good way, but it looks like I'm receiving two times the same digits. So MGCP send it  twice, which is normal.

Is that correct?

Thanks a lot

[R0g22]

Those are for different calls -

//747/75C7CBFD8189/CCAPI/cc_api_call_digit_end:
//745/4BE2386A8188/CCAPI/cc_api_call_digit_end:

From MGCP, they are two different end points/channels/ports -

S0/SU0/DS1-1/3@DID-LRAG248
S0/SU0/DS1-1/2@DID-LRAG248

[cmdemo]

Yes there was two calls on the GW when I took the trace.
First one was I calling someone on site for testing purposes. The second was a user doing the DECT DTMF test.
I didn't sent DTMF, only the user on site doing the test, so there is no reason to get the digit on both calls.
So I manage to redo the test, only two calls with only one user sending DTMF
In this new trace I noticed this message:
cc_relay_digit_begin_for_3way_conference
Could it be possible that the GW thinks we're doin a conference and relays the digits sent to all participants?



Apr 12 2018 10:26:53.417 GMT+2: ISDN Se0/0/1:15 Q931: TX -> SETUP pd = 8 callref = 0x014A
Sending Complete
Bearer Capability i = 0x8090A3
Standard = CCITT
Transfer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0xA98384
Exclusive, Channel 4
Facility i = 0x91AA06800100820100A1080201000201008400
Calling Party Number i = 0x4983, '000237324535'
Plan:Private, Type:Subscriber(local)
Called Party Number i = 0x81, '288501'
Plan:ISDN, Type:Unknown
Apr 12 2018 10:26:53.777 GMT+2: ISDN Se0/0/1:15 Q931: RX <- CALL_PROC pd = 8 callref = 0x814A
Channel ID i = 0xA98384
Exclusive, Channel 4
Apr 12 2018 10:26:53.777 GMT+2: ISDN Se0/0/1:15 Q931: RX <- ALERTING pd = 8 callref = 0x814A
Facility i = 0x91AA068001008201008B0100A11B02010006042B0C09018010436F66656C7920416C6572745F44414C
Progress Ind i = 0x8081 - Call not end-to-end ISDN, may have in-band info
Apr 12 2018 10:26:53.793 GMT+2: MGCP Packet received from 10.245.194.104:2427--->
MDCX 63143 S0/SU0/DS1-1/4@DID-LRAG248 MGCP 0.1
C: D00000000c022335000000F50000014a
I: 178
X: 4
L: p:20, a:PCMU;telephone-event, fmtp:"telephone-event 0-15", s:off, t:b8
M: sendrecv
R: D/[0-9ABCD*#]
S:
Q: process,loop

v=0
o=- 376 0 IN EPN S0/SU0/DS1-1/4@DID-LRAG248
s=Cisco SDP 0
t=0 0
m=audio 17304 RTP/AVP 0 101
c=IN IP4 10.245.136.6
a=rtpmap:101 telephone-event
a=fmtp:101 0-15
<---

Apr 12 2018 10:26:53.793 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/ccCodecPresent:
codec 17

Apr 12 2018 10:26:53.793 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/ccCodecPresent:
codec 17

Apr 12 2018 10:26:53.793 GMT+2: //749/789801D0818A/CCAPI/ccCallModifyExtended:
Nominator=0x3FEB82C0, Params=0x3FEB86F8, Call Id=749
Apr 12 2018 10:26:53.793 GMT+2: //749/789801D0818A/CCAPI/cc_set_mod_voice_port_valueExtended:
Apr 12 2018 10:26:53.793 GMT+2: //750/789801D0818A/CCAPI/ccCallModify:
Nominator=0x20018E30, Params=0x3FEB8CD0, Call Id=750
Apr 12 2018 10:26:53.793 GMT+2: //750/789801D0818A/CCAPI/cc_set_mod_voice_port_value:
Apr 12 2018 10:26:53.797 GMT+2: //749/789801D0818A/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x3F7D731C, Call Id=749
Apr 12 2018 10:26:53.797 GMT+2: //749/789801D0818A/CCAPI/cc_api_call_modify_done:
Apr 12 2018 10:26:53.797 GMT+2: //750/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

Apr 12 2018 10:26:53.797 GMT+2: cc_api_get_xcode_stream : 4983
Apr 12 2018 10:26:53.797 GMT+2: //750/789801D0818A/CCAPI/cc_api_get_xcode_stream:
Apr 12 2018 10:26:53.797 GMT+2: //750/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

Apr 12 2018 10:26:53.797 GMT+2: cc_api_get_xcode_stream : 4983
Apr 12 2018 10:26:53.797 GMT+2: //750/789801D0818A/CCAPI/cc_api_get_xcode_stream:
Apr 12 2018 10:26:53.797 GMT+2: //750/789801D0818A/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x3EDCCD98, Call Id=750
Apr 12 2018 10:26:53.797 GMT+2: //750/789801D0818A/CCAPI/cc_api_call_modify_done:
Apr 12 2018 10:26:53.797 GMT+2: //750/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

Apr 12 2018 10:26:53.797 GMT+2: call_info mainst_callID:0x2EE, peer_callID:0x2ED, confID:0x177, spi_type:6, media_flo_thru:1,num_streams:1, swmtpmsp_present:0

Apr 12 2018 10:26:53.797 GMT+2: //750/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

Apr 12 2018 10:26:53.797 GMT+2: stream[0]: callid:0x2EE, media_passthrough:0
Apr 12 2018 10:26:53.797 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/ccCodecPresent:
codec 17

Apr 12 2018 10:26:53.797 GMT+2: MGCP Packet sent to 10.245.194.104:2427--->
200 63143 OK

v=0
c=IN IP4 10.248.96.248
m=audio 17132 RTP/AVP 0 101
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
<---

Apr 12 2018 10:26:55.153 GMT+2: //743/AD9A11A78187/CCAPI/ccGetCallActiveByCallID:
Apr 12 2018 10:26:56.461 GMT+2: ISDN Se0/0/1:15 Q931: RX <- CONNECT pd = 8 callref = 0x8149
Facility i = 0x91AA068001008201008B0100A11B02010006042B0C09028010436F66656C7920416C6572745F44414C
Connected Number i = 0x0080, '237288504'
Apr 12 2018 10:26:56.465 GMT+2: ISDN Se0/0/1:15 Q931: TX -> CONNECT_ACK pd = 8 callref = 0x0149
Apr 12 2018 10:26:56.713 GMT+2: //749/789801D0818A/CCAPI/ccGetCallActiveByCallID:
Apr 12 2018 10:26:57.321 GMT+2: //747/75C7CBFD8189/CCAPI/ccGetCallActiveByCallID:
Apr 12 2018 10:26:57.413 GMT+2: //749/789801D0818A/CCAPI/cc_handle_inter_digit_timer:
Generate inter-digit timeout CC_EV_CALL_DIGIT_END event
Apr 12 2018 10:26:57.413 GMT+2: //749/789801D0818A/CCAPI/cc_handle_inter_digit_timer:
Generate inter-digit timeout CC_EV_CALL_DIGIT_END event
Apr 12 2018 10:26:57.901 GMT+2: //743/AD9A11A78187/CCAPI/ccGetCallActiveByCallID:
Apr 12 2018 10:26:58.853 GMT+2: //749/789801D0818A/CCAPI/ccGetCallActiveByCallID:
Apr 12 2018 10:26:59.113 GMT+2: //745/4BE2386A8188/CCAPI/ccGetCallActiveByCallID:
Apr 12 2018 10:27:00.585 GMT+2: ISDN Se0/0/1:15 Q931: RX <- CONNECT pd = 8 callref = 0x814A
Facility i = 0x91AA068001008201008B0100A11B02010006042B0C09028010436F66656C7920416C6572745F44414C
Connected Number i = 0x0080, '237288501'
Apr 12 2018 10:27:00.597 GMT+2: ISDN Se0/0/1:15 Q931: TX -> CONNECT_ACK pd = 8 callref = 0x014A
Apr 12 2018 10:27:01.825 GMT+2: //747/75C7CBFD8189/CCAPI/ccGetCallActiveByCallID:
Apr 12 2018 10:27:03.393 GMT+2: //745/4BE2386A8188/CCAPI/ccGetCallActiveByCallID:
Apr 12 2018 10:27:03.537 GMT+2: MGCP Packet received from 10.245.194.104:2427--->
CRCX 63144 S0/SU0/DS1-1/5@DID-LRAG248 MGCP 0.1
C: D000000007f6cfb3000000F50000014b
X: 5
L: p:20, a:PCMU;telephone-event, fmtp:"telephone-event 0-15", s:off, t:b8
M: recvonly
R: D/[0-9ABCD*#]
Q: process,loop
<---

Apr 12 2018 10:27:03.541 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
Interface=0x3F7D731C, Interface Type=6, Destination=, Mode=0x9,
Call Params(Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
Called Number=(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
Subscriber Type Str=, FinalDestinationFlag=FALSE, Outgoing Dial-peer=0, Call Count On=FALSE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=D000000007f6cfb3000000F50000014b)
Apr 12 2018 10:27:03.541 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Apr 12 2018 10:27:03.541 GMT+2: :cc_get_feature_vsa malloc success
Apr 12 2018 10:27:03.541 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Apr 12 2018 10:27:03.541 GMT+2: cc_get_feature_vsa count is 9
Apr 12 2018 10:27:03.541 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Apr 12 2018 10:27:03.541 GMT+2: :FEATURE_VSA attributes are: feature_name:0,feature_time:609440864,feature_id:751
Apr 12 2018 10:27:03.541 GMT+2: //751/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
Total Call Count=4, Call Entry(Call Count On=FALSE, Incoming Call=FALSE)
Apr 12 2018 10:27:03.541 GMT+2: //751/7EA50EF5818B/CCAPI/cc_init_call_entry:
call_init_entry calle is 3D900810,callid is 751
Apr 12 2018 10:27:03.541 GMT+2: //751/7EA50EF5818B/CCAPI/cc_init_call_entry:
Apr 12 2018 10:27:03.541 GMT+2: //751/7EA50EF5818B/CCAPI/cc_insert_guid_pod_entry:
Incoming=FALSE, Call Id=751
Apr 12 2018 10:27:03.541 GMT+2: //751/7EA50EF5818B/CCAPI/cc_set_voice_port_value:
Apr 12 2018 10:27:03.541 GMT+2: //751/7EA50EF5818B/CCAPI/cc_set_voice_port_value:
CC_IF_TELEPHONY: Echo=1, Playout=1
Apr 12 2018 10:27:03.541 GMT+2: //0/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
Call Entry Is Not Found
Apr 12 2018 10:27:03.541 GMT+2: //751/7EA50EF5818B/CCAPI/ccDirectEventToSPI:
Apr 12 2018 10:27:03.541 GMT+2: //751/7EA50EF5818B/CCAPI/ccDirectEventToSPI:exit@10567
Apr 12 2018 10:27:03.541 GMT+2: //751/7EA50EF5818B/CCAPI/ccIFCallSetupRequestPrivate:
SPI Call Setup Request Is Success; Interface Type=6, FlowMode=1
Apr 12 2018 10:27:03.541 GMT+2: //751/7EA50EF5818B/CCAPI/ccCallSetContext:
Context=0x272A2930
Apr 12 2018 10:27:03.541 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/ccCodecPresent:
codec 17

Apr 12 2018 10:27:03.541 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
Interface=0x3EDCCD98, Interface Type=9, Destination=0.0.0.0, Mode=0x9,
Call Params(Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
Called Number=(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
Subscriber Type Str=, FinalDestinationFlag=FALSE, Outgoing Dial-peer=0, Call Count On=TRUE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=D000000007f6cfb3000000F50000014b)
Apr 12 2018 10:27:03.541 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Apr 12 2018 10:27:03.541 GMT+2: :cc_get_feature_vsa malloc success
Apr 12 2018 10:27:03.541 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Apr 12 2018 10:27:03.541 GMT+2: cc_get_feature_vsa count is 10
Apr 12 2018 10:27:03.541 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Apr 12 2018 10:27:03.541 GMT+2: :FEATURE_VSA attributes are: feature_name:0,feature_time:609440640,feature_id:752
Apr 12 2018 10:27:03.541 GMT+2: //752/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
Total Call Count=4, Call Entry(Call Count On=TRUE, Incoming Call=FALSE)
Apr 12 2018 10:27:03.541 GMT+2: //752/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
Total Call Count=5
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/cc_init_call_entry:
call_init_entry calle is 3D8FF980,callid is 752
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/cc_init_call_entry:
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/cc_insert_guid_pod_entry:
Incoming=FALSE, Call Id=752
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/cc_set_voice_port_value:
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/cc_set_voice_port_value:
CC_IF_RTP: vad=0, modem_pro=2, modem_codec=1
Apr 12 2018 10:27:03.541 GMT+2: //0/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
Call Entry Is Not Found
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/ccDirectEventToSPI:
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/ccDirectEventToSPI:exit@10567
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/ccIFCallSetupRequestPrivate:
SPI Call Setup Request Is Success; Interface Type=9, FlowMode=1
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/ccCallSetContext:
Context=0x272A12E8
Apr 12 2018 10:27:03.541 GMT+2: //0/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
Call Entry Is Not Found
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_call_connected:
Interface=0x3EDCCD98, Data Bitmask=0x0, Progress Indication=NULL(0),
Connection Handle=0
Apr 12 2018 10:27:03.541 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/cc_set_conf_start_tstamp:
CALL_ERROR_INFORMATIONAL;
Apr 12 2018 10:27:03.541 GMT+2: cc_set_conf_start_tstamp: no confID set - confID:0

Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_call_connected:
Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_call_connected:exit@6677
Apr 12 2018 10:27:03.541 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_insert_call_active_entry:
Apr 12 2018 10:27:03.545 GMT+2: //752/7EA50EF5818B/CCAPI/cc_incr_if_call_volume:
Apr 12 2018 10:27:03.545 GMT+2: //752/7EA50EF5818B/CCAPI/cc_incr_if_call_volume:
Remote IP Address=0.0.0.0, Hwidb=GigabitEthernet0/0
Apr 12 2018 10:27:03.545 GMT+2: //752/7EA50EF5818B/CCAPI/cc_incr_if_call_volume:
Total Call Count=5, Voip Call Count=5, MMoip Call Count=0
Apr 12 2018 10:27:03.545 GMT+2: //0/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
Call Entry Is Not Found
Apr 12 2018 10:27:03.545 GMT+2: //0/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
Call Entry Is Not Found
Apr 12 2018 10:27:03.545 GMT+2: //0/xxxxxxxxxxxx/CCAPI/cc_api_get_ic_leg_obtained_numbers:
CALL_ERROR_INFORMATIONAL; Call Entry Is Not Found
Apr 12 2018 10:27:03.545 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/cc_set_outpulsed_digits:
Invalid Arguments
Apr 12 2018 10:27:03.545 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_insert_call_active_entry:
Apr 12 2018 10:27:03.545 GMT+2: //751/7EA50EF5818B/CCAPI/cc_incr_if_call_volume:
Apr 12 2018 10:27:03.545 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_proceeding:
Interface=0x3F7D731C, Progress Indication=NULL(0)
Apr 12 2018 10:27:03.557 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_active_notify:
Apr 12 2018 10:27:03.557 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_connected:
Interface=0x3F7D731C, Data Bitmask=0x1, Progress Indication=DESTINATION IS NON ISDN(2),
Connection Handle=0
Apr 12 2018 10:27:03.557 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/cc_set_conf_start_tstamp:
CALL_ERROR_INFORMATIONAL;
Apr 12 2018 10:27:03.557 GMT+2: cc_set_conf_start_tstamp: no confID set - confID:0

Apr 12 2018 10:27:03.557 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_connected:
Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
Apr 12 2018 10:27:03.557 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_connected:exit@6677
Apr 12 2018 10:27:03.557 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
CALL_ERROR_INFORMATIONAL; Call Id Is Invalid=-1
Apr 12 2018 10:27:03.557 GMT+2: //751/7EA50EF5818B/CCAPI/ccCallModify:
Nominator=0x1000, Params=0x3FEB9278, Call Id=751
Apr 12 2018 10:27:03.557 GMT+2: //751/7EA50EF5818B/CCAPI/cc_set_mod_voice_port_value:
Apr 12 2018 10:27:03.557 GMT+2: //751/7EA50EF5818B/CCAPI/ccCallReportDigits:
(callID=0x2EF, digit_event=0x1, enable=TRUE, consume=FALSE)
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=751
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x3F7D731C, callID=0x2EF, disp=0, digit_event=0x1, enable=TRUE, consume=FALSE)
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x3F7D731C, Call Id=751
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=15000(ms), Inter Digit Timeout=10000(ms))
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/ccConferenceCreate:
(confID=0xFFFFFFFF, callID1=0x2EF, gcid=0-0-0-0, tag=0x0)
Apr 12 2018 10:27:03.561 GMT+2: //752/7EA50EF5818B/CCAPI/ccConferenceCreate:
(confID=0xFFFFFFFF, callID2=0x2F0, gcid=0-0-0-0, tag=0x0)
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/ccConferenceCreate:
Conference Id=0xFFFFFFFF, Call Id1=751, Call Id2=752, Tag=0x0
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_bridge_done:
Conference Id=0x178, Source Interface=0x3F7D731C, Source Call Id=751,
Destination Call Id=752, Disposition=0x0, Tag=0xFFFFFFFF
Apr 12 2018 10:27:03.561 GMT+2: //752/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

Apr 12 2018 10:27:03.561 GMT+2: cc_api_get_xcode_stream : 4983
Apr 12 2018 10:27:03.561 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_get_xcode_stream:
Apr 12 2018 10:27:03.561 GMT+2: //752/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

Apr 12 2018 10:27:03.561 GMT+2: call_info mainst_callID:0x2F0, peer_callID:0x2EF, confID:0x178, spi_type:6, media_flo_thru:1,num_streams:1, swmtpmsp_present:0

Apr 12 2018 10:27:03.561 GMT+2: //752/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

Apr 12 2018 10:27:03.561 GMT+2: stream[0]: callid:0x2F0, media_passthrough:0
Apr 12 2018 10:27:03.561 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_bridge_done:
Conference Id=0x178, Source Interface=0x3EDCCD98, Source Call Id=752,
Destination Call Id=751, Disposition=0x0, Tag=0x0
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/cc_generic_bridge_done:
Conference Id=0x178, Source Interface=0x3EDCCD98, Source Call Id=752,
Destination Call Id=751, Disposition=0x0, Tag=0x0
Apr 12 2018 10:27:03.561 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/cc_exchange_calls_mlpp_info:
Unable too Get MLPP nformation for callID 751
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x178, Destination Call Id=752)
Apr 12 2018 10:27:03.561 GMT+2: //752/7EA50EF5818B/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x178, Destination Call Id=751)
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/ccConferenceCreate:

Apr 12 2018 10:27:03.561 GMT+2: confID:0x178; callEntry1 callID1:0x2EF, type:6; callEntry2 callID2:0x2F0, type:9

Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_caps_ind:

Apr 12 2018 10:27:03.561 GMT+2: voice_rtp_nse_payload 0, voice_rtp_sse_payload 118 voice_sprt_payload 120
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_caps_ind:

Apr 12 2018 10:27:03.561 GMT+2: sprt_latency 200, sprt_retries 12
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_caps_ind:
Destination Interface=0x3EDCCD98, Destination Call Id=752, Source Call Id=751,
Caps(Codec=0x1, Fax Rate=0x1, Fax Version:=0, Vad=0x1,
Modem=0x2, Codec Bytes=20, Signal Type=3)
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_caps_ind:
Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
Playout Max=1000(ms), Fax Nom=300(ms))
Apr 12 2018 10:27:03.561 GMT+2: //752/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

Apr 12 2018 10:27:03.561 GMT+2: cc_api_get_xcode_stream : 4983
Apr 12 2018 10:27:03.561 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_get_xcode_stream:
Apr 12 2018 10:27:03.561 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_caps_ind:

Apr 12 2018 10:27:03.561 GMT+2: voice_rtp_nse_payload 100, voice_rtp_sse_payload 118 voice_sprt_payload 120
Apr 12 2018 10:27:03.561 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_caps_ind:

Apr 12 2018 10:27:03.561 GMT+2: sprt_latency 200, sprt_retries 12
Apr 12 2018 10:27:03.561 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_caps_ind:
Destination Interface=0x3F7D731C, Destination Call Id=751, Source Call Id=752,
Caps(Codec=0x1, Fax Rate=0x1, Fax Version:=0, Vad=0x1,
Modem=0x2, Codec Bytes=160, Signal Type=2)
Apr 12 2018 10:27:03.561 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_caps_ind:
Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
Playout Max=1000(ms), Fax Nom=300(ms))
Apr 12 2018 10:27:03.561 GMT+2: //752/7EA50EF5818B/CCAPI/cc_api_caps_ack:
Destination Interface=0x3F7D731C, Destination Call Id=751, Source Call Id=752,
Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_NONE(0x1), Fax Version:=0, Vad=OFF(0x1),
Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=8347)
Apr 12 2018 10:27:03.561 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_caps_ack:
Destination Interface=0x3EDCCD98, Destination Call Id=752, Source Call Id=751,
Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_NONE(0x1), Fax Version:=0, Vad=OFF(0x1),
Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=8347)
Apr 12 2018 10:27:03.565 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x3F7D731C, Call Id=751
Apr 12 2018 10:27:03.565 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_modify_done:
Apr 12 2018 10:27:03.565 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_voice_mode_event:
Call Id=751
Apr 12 2018 10:27:03.565 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_voice_mode_event:
Call Entry(Context=0x272A2930)
Apr 12 2018 10:27:03.565 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_mode_update_ind:exit@15966
Apr 12 2018 10:27:03.565 GMT+2: //751/7EA50EF5818B/CCAPI/cc_process_notify_bridge_done:
Conference Id=0x178, Call Id1=751, Call Id2=752
Apr 12 2018 10:27:03.565 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/ccCodecPresent:
codec 17

Apr 12 2018 10:27:03.565 GMT+2: MGCP Packet sent to 10.245.194.104:2427--->
200 63144 OK
I: 179

v=0
c=IN IP4 10.248.96.248
m=audio 17134 RTP/AVP 0 99 100
a=rtpmap:99 telephone-event/8000
a=fmtp:99 0-15
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
<---

Apr 12 2018 10:27:03.569 GMT+2: //751/7EA50EF5818B/CCAPI/ccSetDigitTimeouts:
Initial Digit Timeout=4000(ms), Inter Digit Timeout=4000(ms)
Apr 12 2018 10:27:03.569 GMT+2: //751/7EA50EF5818B/CCAPI/ccSetDigitTimeouts:
Call Entry(Inter Digit Timeout=4000(ms), Initial Digit Timeout=4000(ms))
Apr 12 2018 10:27:03.569 GMT+2: //751/7EA50EF5818B/CCAPI/ccRestartDigitTimeoutMsec:
Digit Timeout=0, Call Id=751
Apr 12 2018 10:27:03.569 GMT+2: //751/7EA50EF5818B/CCAPI/ccCallReportDigits:
(callID=0x2EF, digit_event=0x1, enable=TRUE, consume=FALSE)
Apr 12 2018 10:27:03.569 GMT+2: //751/7EA50EF5818B/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=751
Apr 12 2018 10:27:03.569 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x3F7D731C, callID=0x2EF, disp=0, digit_event=0x1, enable=TRUE, consume=FALSE)
Apr 12 2018 10:27:03.569 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x3F7D731C, Call Id=751
Apr 12 2018 10:27:03.569 GMT+2: //751/7EA50EF5818B/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=4000(ms), Inter Digit Timeout=4000(ms))
Apr 12 2018 10:27:04.337 GMT+2: ISDN Se0/0/1:15 Q931: TX -> SETUP pd = 8 callref = 0x014B
Sending Complete
Bearer Capability i = 0x8090A3
Standard = CCITT
Transfer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0xA98385
Exclusive, Channel 5
Facility i = 0x91AA06800100820100A11F0201000201008017504F53544520444520474152444520414C454D42455254
Calling Party Number i = 0x4981, '288248'
Plan:Private, Type:Subscriber(local)
Called Party Number i = 0x81, '288511'
Plan:ISDN, Type:Unknown
Apr 12 2018 10:27:04.349 GMT+2: //749/789801D0818A/CCAPI/ccGetCallActiveByCallID:
Apr 12 2018 10:27:04.673 GMT+2: ISDN Se0/0/1:15 Q931: RX <- CALL_PROC pd = 8 callref = 0x814B
Channel ID i = 0xA98385
Exclusive, Channel 5
Apr 12 2018 10:27:04.673 GMT+2: ISDN Se0/0/1:15 Q931: RX <- ALERTING pd = 8 callref = 0x814B
Facility i = 0x91AA068001008201008B0100A11302010006042B0C09018008532E44414C5F4B37
Progress Ind i = 0x8081 - Call not end-to-end ISDN, may have in-band info

Apr 12 2018 10:27:04.673 GMT+2: //747/75C7CBFD8189/CCAPI/cc_api_call_digit_begin:
Apr 12 2018 10:27:04.673 GMT+2: //747/75C7CBFD8189/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x3EDCCD98, Destination Mask=0x1, Destination Call Id=748,
Source Call Id=747, Digit=1, DigitBeginFlags=0x1,
Rtp Timestamp=0xA9BE84B, Rtp Expiration=0x0
Apr 12 2018 10:27:04.673 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_begin:
Apr 12 2018 10:27:04.673 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x3EDCCD98, Destination Mask=0x3, Destination Call Id=746,
Source Call Id=745, Digit=1, DigitBeginFlags=0x1,
Rtp Timestamp=0xDCD8E8A5, Rtp Expiration=0x0
Apr 12 2018 10:27:04.673 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_begin:
Consume mask is not set. Relaying Digit 1 to dstCallId 0x2EA
Apr 12 2018 10:27:04.673 GMT+2: //745/4BE2386A8188/CCAPI/cc_relay_digit_begin_for_3way_conference:
Apr 12 2018 10:27:04.673 GMT+2: //745/4BE2386A8188/CCAPI/cc_relay_digit_begin_for_3way_conference:
Check DTMF relay digit begin for 3way conf
Apr 12 2018 10:27:04.673 GMT+2: //747/75C7CBFD8189/CCAPI/cc_api_call_digit_end:
Apr 12 2018 10:27:04.673 GMT+2: //747/75C7CBFD8189/CCAPI/cc_api_call_digit_end:
Destination Interface=0x3EDCCD98, Destination Mask=0x1, Destination Call Id=748,
Source Call Id=747, Digit=1, Duration=102,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
Apr 12 2018 10:27:04.673 GMT+2: //747/75C7CBFD8189/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
Apr 12 2018 10:27:04.673 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_end:
Apr 12 2018 10:27:04.673 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_end:
Destination Interface=0x3EDCCD98, Destination Mask=0x3, Destination Call Id=746,
Source Call Id=745, Digit=1, Duration=92,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
Apr 12 2018 10:27:04.673 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
Apr 12 2018 10:27:04.673 GMT+2: //745/4BE2386A8188/CCAPI/cc_api_call_digit_end:
Consume mask is not set. Relaying Digit 1 to dstCallId 0x2EA
Apr 12 2018 10:27:04.673 GMT+2: //745/4BE2386A8188/CCAPI/cc_relay_digit_end_for_3way_conference:
Apr 12 2018 10:27:04.673 GMT+2: //745/4BE2386A8188/CCAPI/cc_relay_digit_end_for_3way_conference:
Check DTMF relay digit end for 3way conf
Apr 12 2018 10:27:04.677 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/ccGetVoicePortsOnPlatform:
voice platform ports 0

Apr 12 2018 10:27:04.677 GMT+2: MGCP Packet sent to 10.245.194.104:2427--->
NTFY 683349582 S0/SU0/DS1-1/3@DID-LRAG248 MGCP 0.1
N: ca@10.245.194.104:2427
X: 3
O: D/1
<---

Apr 12 2018 10:27:04.677 GMT+2: //-1/xxxxxxxxxxxx/CCAPI/ccGetVoicePortsOnPlatform:
voice platform ports 0