DTMF tones not working

[shiber32]

Hello,

I'm having issues with dtmf tones with a customer, DTMF tones do not seem work after call is established, I have enabled debug for 'voip rtp session dtmf-relay' but I'm a bit lost honestly. As far as I can see negotiation is completed but it shows the following messages before codec negotiation is completed, not sure if this is actually the problem:

Dec 17 15:31:20.400: //54944/299C3F298370/SIP/Info/critical/8193/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay
Dec 17 15:31:20.400: //54944/299C3F298370/SIP/Info/info/1/sipSPIGetSDPDirectionAttribute: No direction attribute present or multiple direction attributes that can't be handled for m-l

See below the logs of a call with the debug for voip rtp session dtmf-relay enabled (call is established at 15:31:19.006):

Received:
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP IP_addr_Y:5060;branch=z9hG4bK1A73E16FD
Record-Route: <sip:IP_addr_X:5060;lr>
From: "Voice_3" <sip:3229203@sip.domain.com>;tag=C424E577-26A3
To: <sip:00385951000444@sip.domain.com>;tag=b1295d083p
Call-ID: 364E372E-5E8511EC-83758C6C-AF859002@IP_addr_Y
CSeq: 102 INVITE
Contact: <sip:00385951000444@IP_addr_X:5060>
Require: 100rel
RSeq: 1
Content-Type: application/sdp
Content-Length: 232

v=0
o=SINATRA$ 1651045 1 IN IP4 IP_addr_X
s=-
c=IN IP4 IP_addr_X
t=0 0
m=audio 10106 RTP/AVP 18 101
a=sendrecv
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=ptime:20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

Dec 17 15:31:19.006: //54944/299C3F298370/SIP/Info/verbose/1024/sipSPICheckResponseExt: Got new RR header
Dec 17 15:31:19.007: //54944/299C3F298370/SIP/Info/verbose/1024/sipSPICheckResponseExt: This is first RR in this dialog
Dec 17 15:31:19.007: //54944/299C3F298370/SIP/Info/critical/4096/sipSPICheckReliableProvStringtag: Unable to access supported header values
Dec 17 15:31:19.007: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentGTD: No GTD found in inbound container
Dec 17 15:31:19.007: //54944/299C3F298370/SIP/Info/verbose/4096/sipSPIUreasonHeader_to_ccCause: Cause=0
Dec 17 15:31:19.007: //54944/299C3F298370/SIP/Info/info/8192/sipSPIProcessSessionID: SessionID header not present - create uuid
Dec 17 15:31:19.007: //54944/299C3F298370/SIP/Info/info/8192/sipSPIGenerateSessionUUID: Generate uuid
Dec 17 15:31:19.007: //54944/299C3F298370/SIP/Info/info/8192/sipSPIGenerateSessionUUID: generated uuid - 0bddb1d82efe503cbccf42a3e04832e2
Dec 17 15:31:19.007: //54944/299C3F298370/SIP/Info/info/8192/sipSPIGetTDSessionID: Get session-ID local uuid - 70ba67cf7f7d5f5e8254a852c218f64c remote uuid - 00000000000000000000000000000000
Dec 17 15:31:19.007: //54944/299C3F298370/SIP/Info/info/8192/sipSPICreateAndPopulateSessionID: update remoteuuid
Dec 17 15:31:19.007: //54944/299C3F298370/SIP/Info/notify/8192/sipSPI_Add_SessionIDtoTDContainer: localUUID - 0bddb1d82efe503cbccf42a3e04832e2remoteUUID - 70ba67cf7f7d5f5e8254a852c218f64c
Dec 17 15:31:19.007: //54944/299C3F298370/SIP/Info/verbose/1/sipSPIDoMediaNegotiation: Number of m-lines = 1
Dec 17 15:31:19.007: //54944/299C3F298370/SIP/Info/verbose/1/sipSPIValidateConnectionAddress: Dest port = 10106
SIP: Attribute mid, level 1 instance 1 not found.
Dec 17 15:31:19.008: //54944/299C3F298370/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1
Dec 17 15:31:19.008: //54944/299C3F298370/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr
Dec 17 15:31:19.008: //54944/299C3F298370/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = IP_addr_Y
Dec 17 15:31:19.008: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec No Codec
Dec 17 15:31:19.008: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 96
Dec 17 15:31:19.008: //-1/xxxxxxxxxxxx/SIP/Info/critical/1/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved as its in use by other codec
Dec 17 15:31:19.008: //-1/xxxxxxxxxxxx/SIP/Info/critical/1/sipSPIUpdateDynamicPT: Requested payload-Type (101) is reserved by another application
Dec 17 15:31:19.008: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98
Dec 17 15:31:19.008: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 101
Dec 17 15:31:19.008: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIAllocateFreeDynamicPT: Allocating free Dynamic Payload : 98 for Codec:
Dec 17 15:31:19.008: //54944/299C3F298370/SIP/Media/sipSPISelectCodecVersion: g729r8 flavor of g729 codec will be used
Dec 17 15:31:19.008: //54944/299C3F298370/SIP/Info/notify/1/sipSPIDoAudioNegotiation: Codec (g729r8) Negotiation Successful on Static Payload for m-line 1
Dec 17 15:31:19.008: //54944/299C3F298370/SIP/Info/verbose/1/sipSPIDoPtimeNegotiation: One ptime attribute found - value:20
Dec 17 15:31:19.008: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_ptime_to_codec_bytes: Values :Codec: g729r8 ptime :20, codecbytes: 20
Dec 17 15:31:19.009: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/convert_codec_bytes_to_ptime: Values :Codec: g729r8 codecbytes :20, ptime: 20
Dec 17 15:31:19.009: //54944/299C3F298370/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:20, Negotiated ptime:20 Negotiated codec bytes: 20 for codec g729r8
Dec 17 15:31:19.009: //54944/299C3F298370/SIP/Info/info/8/sipSPISetFaxFlags: FAX_PASSTHROUGH = 0, END_FAX_PASSTHROUGH = 0
Dec 17 15:31:19.009: //54944/299C3F298370/SIP/Info/info/1/sipSPIDoDTMFRelayNegotiation: m-line index 1
Dec 17 15:31:19.009: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec
Dec 17 15:31:19.009: //-1/xxxxxxxxxxxx/SIP/Info/notify/1/sipSPICheckDynPayloadUse: Dynamic payload(101) reserved for codec
Dec 17 15:31:19.009: //-1/xxxxxxxxxxxx/SIP/Info/info/1/sipSPIUpdateDynamicPayloadunused: Unreserving dynamic payload type 98
Dec 17 15:31:19.009: //54944/299C3F298370/SIP/Info/notify/1/sipSPIReserveRtpNtePayload: Reserved the payload type 101 for RTP-NTE
Dec 17 15:31:19.009: //54944/299C3F298370/SIP/Info/info/32/sipSPIDoDTMFRelayNegotiation: RTP-NTE DTMF relay option
Dec 17 15:31:19.009: //54944/299C3F298370/SIP/Info/info/1/sipSPIDoDTMFRelayNegotiation: Case of full named event(NE) match in fmtp list of events.
Dec 17 15:31:19.009: //-1/xxxxxxxxxxxx/SIP/Info/info/8193/sip_sdp_get_modem_relay_cap_params: ptype is 18
Dec 17 15:31:19.009: //-1/xxxxxxxxxxxx/SIP/Info/info/8193/sip_sdp_get_modem_relay_cap_params: ptype is 101
Dec 17 15:31:19.009: //-1/xxxxxxxxxxxx/SIP/Info/info/8193/sip_sdp_get_modem_relay_cap_params: encname is telephone-event
Dec 17 15:31:19.009: //-1/xxxxxxxxxxxx/SIP/Info/info/8209/sip_sdp_get_modem_relay_cap_params: mer_dtmf_found 0
Dec 17 15:31:19.009: //-1/xxxxxxxxxxxx/SIP/Info/info/8209/sip_sdp_get_modem_relay_cap_params: V150 NSE payload = 0, SSE payload = 0, SPRT payload=0
Dec 17 15:31:19.009: //54944/299C3F298370/SIP/Info/critical/8193/sip_select_modem_relay_params: X-tmr not present in SDP. Disable modem relay
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/Info/info/1/sipSPIGetSDPDirectionAttribute: No direction attribute present or multiple direction attributes that can't be handled for m-line:1 and num-a-lines:0
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/Info/notify/1/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1
payload_type=18, codec_bytes=20, codec=g729r8, dtmf_relay=rtp-nte
stream_type=voice+dtmf (1), dest_ip_address=IP_addr_X, dest_port=10106
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/State/sipSPIChangeStreamState: Stream (callid = -1) State changed from (STREAM_DEAD) to (STREAM_ADDING)
Dec 17 15:31:19.010: //-1/xxxxxxxxxxxx/SIP/Info/sipSPI_Check_If_ICE_Needed: CANDIDATE attribute, level 1not found.
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/Info/info/131073/sipSPIDoQoSNegotiationWithMediaLine: QOS negotiation for mline_index 1
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/Info/notify/131072/sipSPIDoStreamQoSNegotiation: Best effort
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/Info/info/4096/ccsip_iwf_handle_generic_event:
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_SENT_AWAIT_SDP, event:E_SIP_IWF_EV_CALL_BRIDGE
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/State/ccsip_cnfsm_debugs: IWF:new_container:sip_iwf_main_container
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/Info/verbose/4096/ccsip_iwf_process_event: IWF - cnfsm ret 2
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/Media/sipSPIUpdCallWithSdpInfo:
Preferred Codec : g722-64, bytes :160
Preferred DTMF relay : rtp-nte
Preferred NTE payload : 101
Early Media : No
Delayed Media : No
Bridge Done : No
New Media : No
DSP DNLD Reqd : No

Dec 17 15:31:19.010: //54944/299C3F298370/SIP/Info/notify/6/sipSPIValidateStreamAddrType: stream:1, Mode : 1
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/Info/verbose/513/resolve_media_ip_address_to_bind: Media already bound, use existing source_media_ip_addr
Dec 17 15:31:19.010: //54944/299C3F298370/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = IP_addr_Y
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/Info/info/4096/ccsip_offer_ans_handle_rcvd_sdp:
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/State/ccsip_cnfsm_debugs: OA:cur_container:ccsip_offer_ans_main_container, cur_state:S_SIP_EARLY_DIALOG_OFFER_SENT, event:E_SIP_INVITE_RESP_SDP_RCVD
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/Info/info/4096/ccsip_offer_ans_is_incoming_invite_resp_answer_valid: TRUE
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/Info/info/4096/ccsip_offer_ans_common_answer_rcvd_hdlr:
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/Info/info/4096/ccsip_iwf_handle_network_event:
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/State/ccsip_cnfsm_debugs: IWF:cur_container:sip_iwf_default_early_dialog_container, cur_state:S_SIP_IWF_SDP_SENT_AWAIT_SDP, event:E_SIP_IWF_EV_RCVD_SDP
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/Info/info/4096/sip_iwf_def_ed_rcvd_sdp_answer_hdlr:
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/Info/info/131074/sipSPIBwCacCalcNegoAudioBandwidth: max audio bw (including pak overhead) from negotiated stream : codec g729r8 bw 24000 bps index 1
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted BW Option 1 flow mode flow-through
audio bw 24000 bps video bw 0 bps fax bw 0 bps total bw 24000 bps accounted bw 0 bps
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/Info/info/131072/sipSPIBwCacUpdateInterfaceBw: bwcac updating interface GigabitEthernet0/0/0 bw 24
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/Info/info/131072/sipSPIBwCacUpdateAccountedBw: bwcac update accounted bw (initial answer) accounted bw adjusted to 24000 delta 24000
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/State/ccsip_cnfsm_debugs: IWF:next_state:S_SIP_IWF_SDP_DONE
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/State/ccsip_cnfsm_debugs: OA:next_state:S_SIP_EARLY_DIALOG_OFFER_ANSWER_COMPLETE
Dec 17 15:31:19.011: //54944/299C3F298370/SIP/Media/sipSPIUpdCallWithSdpInfo:
Stream type : voice+dtmf
Media line : 1
State : STREAM_ADDING (2)
Stream address type : 1
Callid : 54944
Negotiated Codec : g729r8, bytes :20
Nego. Codec payload : 18 (tx), 18 (rx)
Negotiated DTMF relay : rtp-nte
Negotiated NTE payload : 101 (tx), 101 (rx)
Negotiated CN payload : 0
Media Srce Addr/Port : [IP_addr_Y]:8194
Media Dest Addr/Port : [IP_addr_X]:10106

Dec 17 15:31:19.012: //54944/299C3F298370/SIP/Info/critical/1024/sipSPIProcessHistoryInfoHeader: No HI headers recvd from app container
Dec 17 15:31:19.012: //54944/299C3F298370/SIP/Info/info/133120/sipSPIBwCacIsDialPeerBwAvailable: bwcac NOP dial-peer bw available tag 100
Dec 17 15:31:19.012: //54944/299C3F298370/SIP/Info/notify/1/sipSPIBwCacIsInterfaceBwAvailable: bwcac interface bw threshold not configured
Dec 17 15:31:19.012: //54944/299C3F298370/SIP/Info/info/131072/sipSPIBwCacVerifyBwThreshold: bwcac verify bw threshold, bw available allow call total bw 24000 bps
Dec 17 15:31:19.012: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentQSIG: No QSIG Body found in inbound container
Dec 17 15:31:19.012: //-1/xxxxxxxxxxxx/SIP/Info/critical/4096/sipSPIGetContentQ931: No RawMsg Body found in inbound container
Dec 17 15:31:19.012: //-1/xxxxxxxxxxxx/SIP/Info/critical/12288/sipSPICreateNewRawMsg: No Data to form The Raw Message

Codecs used:

voice class codec 100
codec preference 1 g722-64
codec preference 2 g711ulaw
codec preference 3 g711alaw
codec preference 4 g729r8

Dial-peers config:

dial-peer voice 100 voip
destination-pattern .T
session protocol sipv2
session target sip-server
voice-class codec 100
voice-class sip dtmf-relay force rtp-nte
dtmf-relay rtp-nte
fax protocol pass-through g711ulaw
no vad
!
dial-peer voice 102 voip
destination-pattern 3229...
session protocol sipv2
session target sip-server
voice-class codec 100
voice-class sip dtmf-relay force rtp-nte
dtmf-relay rtp-nte
fax protocol pass-through g711ulaw
no vad
!
dial-peer voice 200 voip
session protocol sipv2
session target sip-server
incoming called-number 3229200
voice-class codec 100
voice-class sip dtmf-relay force rtp-nte
dtmf-relay rtp-nte
no vad
!
dial-peer voice 201 voip
session protocol sipv2
session target sip-server
incoming called-number 3229201
voice-class codec 100
voice-class sip dtmf-relay force rtp-nte
dtmf-relay rtp-nte
no vad
!
dial-peer voice 202 voip
session protocol sipv2
session target sip-server
incoming called-number 3229202
voice-class codec 100
voice-class sip dtmf-relay force rtp-nte
dtmf-relay rtp-nte
no vad
!
dial-peer voice 203 voip
session protocol sipv2
session target sip-server
incoming called-number 3229203
voice-class codec 100
voice-class sip dtmf-relay force rtp-nte
dtmf-relay rtp-nte
no vad

Any help or suggestion would be much appreciated.