I’ve been having trouble getting RFC 2833 / 4733 DTMF to work. I’m using Asterisk 15.4 running on the FreePBX Distro with Linphone softphones. I have posted about this on the FreePBX forum and the Linphone developer mailing list, and I’m still stuck.
DTMF is not working (i.e. I press a key, and the other side doesn’t recognize it). After several hours of debugging, it seems to be related to codec frequency. If I enable a codec in my Linphone settings that uses a frequency greater than 8000 Hz (e.g. speex, opus, etc.) even if that codec is not negotiated, DTMF fails.
I enabled rtp and pjsip debugging and ran some tests. I added the logs below.
Both calls wind up using the same codec, but DTMF works on one and it doesn’t on the other. Obviously, on the successful call we see the DTMF packets are recognized as RFC2833 and they are not on the failed call. I just can’t understand why. Could it be because when it worked the payload number for telephone-event
was 101 and when it didn’t it was 98? That’s a real shot in the dark, but I am completely stumped.
Looking at the Asterisk code base, I saw this line which seems like it could be related, but I don’t know the code well enough to know what’s going on there. I could be barking up totally the wrong tree.
Any ideas on what’s going on?
Successful Call (DTMF worked)
Initial INVITE from Caller
[2018-04-06 14:31:55] VERBOSE[6791] res_pjsip_logger.c: <--- Received SIP request (1322 bytes) from TLS:192.168.1.10:36623 --->
INVITE sip:1101@freepbx.server.com SIP/2.0
Via: SIP/2.0/TLS 192.168.1.10:36623;branch=z9hG4bK.x4Iowo7HJ;rport
From: <sip:1004@freepbx.server.com>;tag=iQuPf4GBP
To: sip:1101@freepbx.server.com
CSeq: 20 INVITE
Call-ID: Al9P0yUtod
Max-Forwards: 70
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 702
Contact: <sip:1004@192.168.1.10:36623;transport=tls>;+sip.instance="<urn:uuid:5a3150e3-5e90-4984-b12b-2cfc5ad4a15e>"
User-Agent: LinphoneAndroid/3.3.2.2-TG (belle-sip/1.6.3)
v=0
o=1004 3003 1159 IN IP4 192.168.1.10
s=Talk
c=IN IP4 192.168.1.10
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7076 RTP/SAVP 96 0 8 18 101
a=rtpmap:96 speex/8000
a=fmtp:96 vbr=on
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:Yl6b4HKe7GanfgObzlZmCS3TX1iZLmOMW57JJjJ2
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:gkfj8LHaB1PZyV8LLdGVDnMu88YT1FxZPwcgcwL8
a=crypto:3 AES_256_CM_HMAC_SHA1_80 inline:kE1BFsEgifzQw9LAyyD80aaIMeFrOlwf1vA4T44PsKS7tlEAHLF552MJ5uGPKg==
a=crypto:4 AES_256_CM_HMAC_SHA1_32 inline:rXGPaoCCvjC0KuwA0aG3HgmHFCGMd5qGeTfGZKYf2WPxhHWKbRYc7MVlrYOsug==
a=rtcp-fb:* ccm tmmbr
Notify Caller of Answer
[2018-04-06 14:31:56] VERBOSE[32423] res_pjsip_logger.c: <--- Transmitting SIP response (1040 bytes) to TLS:192.168.1.10:36623 --->
SIP/2.0 200 OK
Via: SIP/2.0/TLS 192.168.1.10:36623;rport=36623;received=192.168.1.10;branch=z9hG4bK.g2CzEVYhu
Call-ID: Al9P0yUtod
From: <sip:1004@freepbx.server.com>;tag=iQuPf4GBP
To: <sip:1101@freepbx.server.com>;tag=30828a9d-cdbf-479a-9016-b48215b31e8c
CSeq: 21 INVITE
Server: FPBX-14.0.2.10(15.2.2)
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Contact: <sip:192.168.1.5:5061;transport=TLS>
Supported: 100rel, timer, replaces, norefersub
P-Asserted-Identity: "User 1" <sip:1101@freepbx.server.com>
Content-Type: application/sdp
Content-Length: 387
v=0
o=- 3003 1161 IN IP4 192.168.1.5
s=Asterisk
c=IN IP4 192.168.1.5
t=0 0
m=audio 12880 RTP/SAVP 0 8 18 101
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:k7d54Fzm1HMFS2WU3xr0zyepyrShTeTIqa03aofs
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv
RTP Stream
[2018-04-06 14:31:57] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 004392, ts 565097400, len 000170)
[2018-04-06 14:31:57] VERBOSE[23736][C-000000a6] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000005, ts 565097565, len 000160)
[2018-04-06 14:31:57] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 004393, ts 565097560, len 000170)
[2018-04-06 14:31:57] VERBOSE[23736][C-000000a6] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000006, ts 565097725, len 000160)
[2018-04-06 14:31:57] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 004394, ts 565097720, len 000170)
[2018-04-06 14:31:57] VERBOSE[23736][C-000000a6] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000007, ts 565097885, len 000160)
.....
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 101, seq 000092, ts 602617351, len 000004)
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.1.10:7076 (type 101, seq 000092, ts 602617351, len 000004, mark 1, event 00000008, end 0, duration 00160)
[2018-04-06 14:31:59] DEBUG[23733][C-000000a6] res_rtp_asterisk.c: - RTP 2833 Event: 00000008 (len = 4)
[2018-04-06 14:31:59] VERBOSE[23736][C-000000a6] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000110, ts 565114365, len 000160)
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 004498, ts 565114360, len 000170)
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 101, seq 000093, ts 602617351, len 000004)
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.1.10:7076 (type 101, seq 000093, ts 602617351, len 000004, mark 0, event 00000008, end 0, duration 00320)
[2018-04-06 14:31:59] DEBUG[23733][C-000000a6] res_rtp_asterisk.c: - RTP 2833 Event: 00000008 (len = 4)
[2018-04-06 14:31:59] VERBOSE[23736][C-000000a6] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000111, ts 565114525, len 000160)
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 004499, ts 565114520, len 000170)
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 101, seq 000094, ts 602617351, len 000004)
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.1.10:7076 (type 101, seq 000094, ts 602617351, len 000004, mark 0, event 00000008, end 0, duration 00480)
[2018-04-06 14:31:59] DEBUG[23733][C-000000a6] res_rtp_asterisk.c: - RTP 2833 Event: 00000008 (len = 4)
[2018-04-06 14:31:59] VERBOSE[23736][C-000000a6] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000112, ts 565114685, len 000160)
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 004500, ts 565114680, len 000170)
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 101, seq 000095, ts 602617351, len 000004)
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.1.10:7076 (type 101, seq 000095, ts 602617351, len 000004, mark 0, event 00000008, end 0, duration 00640)
[2018-04-06 14:31:59] DEBUG[23733][C-000000a6] res_rtp_asterisk.c: - RTP 2833 Event: 00000008 (len = 4)
[2018-04-06 14:31:59] VERBOSE[23736][C-000000a6] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000113, ts 565114845, len 000160)
[2018-04-06 14:31:59] VERBOSE[23733][C-000000a6] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 004501, ts 565114840, len 000170)
Failed Call (DTMF didn’t work)
Initial INVITE from Caller
[2018-04-06 14:32:19] VERBOSE[6791] res_pjsip_logger.c: <--- Received SIP request (1406 bytes) from TLS:192.168.1.10:36623 --->
INVITE sip:1101@freepbx.server.com SIP/2.0
Via: SIP/2.0/TLS 192.168.1.10:36623;branch=z9hG4bK.09oNseORt;rport
From: <sip:1004@freepbx.server.com>;tag=0bVmil7L7
To: sip:1101@freepbx.server.com
CSeq: 20 INVITE
Call-ID: giaAPEO5oz
Max-Forwards: 70
Supported: replaces, outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 786
Contact: <sip:1004@192.168.1.10:36623;transport=tls>;+sip.instance="<urn:uuid:5a3150e3-5e90-4984-b12b-2cfc5ad4a15e>"
User-Agent: LinphoneAndroid/3.3.2.2-TG (belle-sip/1.6.3)
v=0
o=1004 1441 2486 IN IP4 192.168.1.10
s=Talk
c=IN IP4 192.168.1.10
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7076 RTP/SAVP 96 97 0 8 18 101 98
a=rtpmap:96 speex/16000
a=fmtp:96 vbr=on
a=rtpmap:97 speex/8000
a=fmtp:97 vbr=on
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/16000
a=rtpmap:98 telephone-event/8000
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:SlMxT019CunqOGrAXwXreRhm6kJ9dw8X3Gh6/LhV
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:pWWTCwxlIGi20WcvZCAJC0Jo29dIrJ/9VmDuk0Ig
a=crypto:3 AES_256_CM_HMAC_SHA1_80 inline:PkYK/oG2F8U53pE6Y/1gu05TqqxgqsfFmEegunUOyMsTpNPA8gAEE7QXULB16Q==
a=crypto:4 AES_256_CM_HMAC_SHA1_32 inline:US4TIkQ3sl1XK28C7LZPBMGzJBaCGJqxMVt3sg2PBZFIcwv3KomV8ZWZ3DyvRw==
a=rtcp-fb:* ccm tmmbr
Notify Caller of Answer
[2018-04-06 14:32:21] VERBOSE[30966] res_pjsip_logger.c: <--- Transmitting SIP response (1037 bytes) to TLS:192.168.1.10:36623 --->
SIP/2.0 200 OK
Via: SIP/2.0/TLS 192.168.1.10:36623;rport=36623;received=192.168.1.10;branch=z9hG4bK.MANUueCbB
Call-ID: giaAPEO5oz
From: <sip:1004@freepbx.server.com>;tag=0bVmil7L7
To: <sip:1101@freepbx.server.com>;tag=1add4390-017a-4856-9973-9946756bba26
CSeq: 21 INVITE
Server: FPBX-14.0.2.10(15.2.2)
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Contact: <sip:192.168.1.5:5061;transport=TLS>
Supported: 100rel, timer, replaces, norefersub
P-Asserted-Identity: "User 1" <sip:1101@freepbx.server.com>
Content-Type: application/sdp
Content-Length: 384
v=0
o=- 1441 2488 IN IP4 192.168.1.5
s=Asterisk
c=IN IP4 192.168.1.5
t=0 0
m=audio 16570 RTP/SAVP 0 8 18 98
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:oVH9HZ2j56kvQFRcwOdlEi550fdfu7fBr9RhTHRN
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=ptime:20
a=maxptime:150
a=sendrecv
a=rtpmap:98 telephone-event/8000
a=fmtp:98 0-16
RTP Stream
[2018-04-06 14:32:21] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000004, ts 3208992109, len 000160)
[2018-04-06 14:32:21] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019276, ts 3208992104, len 000170)
[2018-04-06 14:32:21] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000005, ts 3208992269, len 000160)
[2018-04-06 14:32:21] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019277, ts 3208992264, len 000170)
[2018-04-06 14:32:21] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000006, ts 3208992429, len 000160)
[2018-04-06 14:32:21] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019278, ts 3208992424, len 000170)
[2018-04-06 14:32:21] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000007, ts 3208992589, len 000160)
[2018-04-06 14:32:21] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019279, ts 3208992584, len 000170)
[2018-04-06 14:32:21] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000008, ts 3208992749, len 000160)
[2018-04-06 14:32:21] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019280, ts 3208992744, len 000170)
.......
[2018-04-06 14:32:23] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000078, ts 4113917409, len 000004)
[2018-04-06 14:32:23] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000096, ts 3209006829, len 000160)
[2018-04-06 14:32:23] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019368, ts 3209006824, len 000170)
[2018-04-06 14:32:23] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000079, ts 4113917409, len 000004)
[2018-04-06 14:32:23] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000097, ts 3209006989, len 000160)
[2018-04-06 14:32:23] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019369, ts 3209006984, len 000170)
[2018-04-06 14:32:23] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000080, ts 4113917409, len 000004)
[2018-04-06 14:32:23] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000098, ts 3209007149, len 000160)
[2018-04-06 14:32:23] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019370, ts 3209007144, len 000170)
[2018-04-06 14:32:23] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000081, ts 4113917409, len 000004)
[2018-04-06 14:32:23] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000099, ts 3209007309, len 000160)
[2018-04-06 14:32:23] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019371, ts 3209007304, len 000170)
[2018-04-06 14:32:23] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000082, ts 4113917409, len 000004)
[2018-04-06 14:32:23] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000082, ts 4113917409, len 000014)
[2018-04-06 14:32:23] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000082, ts 4113917409, len 000014)
........
[2018-04-06 14:32:24] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000124, ts 4113924369, len 000004)
[2018-04-06 14:32:24] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000139, ts 3209013709, len 000160)
[2018-04-06 14:32:24] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019411, ts 3209013704, len 000170)
[2018-04-06 14:32:24] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000125, ts 4113924369, len 000004)
[2018-04-06 14:32:24] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000140, ts 3209013869, len 000160)
[2018-04-06 14:32:24] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019412, ts 3209013864, len 000170)
[2018-04-06 14:32:24] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000126, ts 4113924369, len 000004)
[2018-04-06 14:32:24] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000141, ts 3209014029, len 000160)
[2018-04-06 14:32:24] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019413, ts 3209014024, len 000170)
[2018-04-06 14:32:24] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000127, ts 4113924369, len 000004)
[2018-04-06 14:32:24] VERBOSE[23851][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.20:48038 (type 00, seq 000142, ts 3209014189, len 000160)
[2018-04-06 14:32:24] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Sent RTP packet to 192.168.1.10:7076 (type 00, seq 019414, ts 3209014184, len 000170)
[2018-04-06 14:32:24] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000128, ts 4113924369, len 000004)
[2018-04-06 14:32:24] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000128, ts 4113924369, len 000014)
[2018-04-06 14:32:24] VERBOSE[23850][C-000000a7] res_rtp_asterisk.c: Got RTP packet from 192.168.1.10:7076 (type 98, seq 000128, ts 4113924369, len 000014)