I recently upgraded to FreePBX 14 (on the official distro), and DTMF stopped working (ie 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.
I’m using linphone on Android and Windows as my softphones. 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. Given that situation, I found this FreeSWITCH bug which I thought might also apply to FreePBX, but as far as I can tell, that’s not what’s going on here.
I enabled rtp and pjsip debugging and ran some tests. I added the logs below.
Both calls wind up using the same codec, but one works and one doesn’t. 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 over 100 and when it didn’t it was under 100? That’s a real shot in the dark, but I am completely stumped.
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:[email protected] SIP/2.0
Via: SIP/2.0/TLS 192.168.1.10:36623;branch=z9hG4bK.x4Iowo7HJ;rport
From: <sip:[email protected]>;tag=iQuPf4GBP
To: sip:[email protected]
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:[email protected]: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:[email protected]>;tag=iQuPf4GBP
To: <sip:[email protected]>;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:[email protected]>
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:[email protected] SIP/2.0
Via: SIP/2.0/TLS 192.168.1.10:36623;branch=z9hG4bK.09oNseORt;rport
From: <sip:[email protected]>;tag=0bVmil7L7
To: sip:[email protected]
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:[email protected]: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:[email protected]>;tag=0bVmil7L7
To: <sip:[email protected]>;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:[email protected]>
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)