DTMF Issue since upgrade from 11.21 to 13.24.1

Asterisk Asterisk Support
1

Hi,

Have sporadic case where DTMF for the Confbridge pin returns invalidpin. It works sometimes and other times not. I have verified channel is alaw and dtmfmode is rfc2833. I can confirm that there is DTMF being received in verbose correctly, also verified pcap on call to check sip-info. See below; the confbridge pin is 1645. The one thing I do notice is that there 4 lines of DTMF verbose each for digits 1,4,5,# and oddly 6 lines for digit 6. Also then I notice RTP Learning Complete after this digit. Can anyone give me any pointers? I’m assuming digit 6 is not read correctly from the confbridge app but the questing is why?

[2018-12-06 18:09:07] VERBOSE[158089][C-00012dac] pbx_builtins.c: Goto (10989-1143-routes,conf-11433,1)
[2018-12-06 18:09:07] VERBOSE[158089][C-00012dac] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:1] Progress("SIP/peer1-3198a7-0002a61d", "")
[2018-12-06 18:09:07] VERBOSE[158089][C-00012dac] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:2] Noop("SIP/peer1-3198a7-0002a61d", "")
[2018-12-06 18:09:07] VERBOSE[158089][C-00012dac] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:3] Wait("SIP/peer1-3198a7-0002a61d", "1")
[2018-12-06 18:09:07] VERBOSE[158089][C-00012dac] res_rtp_asterisk.c: 0x7f68e5d224a0 -- Strict RTP switching to RTP target address xx.xx.xx.xx:17676 as source
[2018-12-06 18:09:08] VERBOSE[158089][C-00012dac] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:4] Confbridge("SIP/peer1-3198a7-0002a61d", "11433_bridge,11433_bridge,11433_user")
[2018-12-06 18:09:08] VERBOSE[158089][C-00012dac] file.c: <SIP/peer1-3198a7-0002a61d> Playing 'conf-getpin.alaw' (language 'uk')

[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF begin '1' received on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF begin ignored '1' on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF end '1' received on SIP/peer1-3198a7-0002a61d, duration 91 ms
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF end passthrough '1' on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF begin '6' received on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF begin ignored '6' on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF end '6' received on SIP/peer1-3198a7-0002a61d, duration 93 ms
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF end passthrough '6' on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF end '6' received on SIP/peer1-3198a7-0002a61d, duration 93 ms
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF end passthrough '6' on SIP/peer1-3198a7-0002a61d

[2018-12-06 18:09:12] VERBOSE[158089][C-00012dac] res_rtp_asterisk.c: 0x7f68e5d224a0 -- Strict RTP learning complete - Locking on source address xx.xx.xx.xx:17676

[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF begin '4' received on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF begin ignored '4' on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF end '4' received on SIP/peer1-3198a7-0002a61d, duration 97 ms
[2018-12-06 18:09:12] DTMF[158089][C-00012dac] channel.c: DTMF end passthrough '4' on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:13] DTMF[158089][C-00012dac] channel.c: DTMF begin '5' received on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:13] DTMF[158089][C-00012dac] channel.c: DTMF begin ignored '5' on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:13] DTMF[158089][C-00012dac] channel.c: DTMF end '5' received on SIP/peer1-3198a7-0002a61d, duration 100 ms
[2018-12-06 18:09:13] DTMF[158089][C-00012dac] channel.c: DTMF end passthrough '5' on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:13] DTMF[158089][C-00012dac] channel.c: DTMF begin '#' received on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:13] DTMF[158089][C-00012dac] channel.c: DTMF begin ignored '#' on SIP/peer1-3198a7-0002a61d
[2018-12-06 18:09:13] DTMF[158089][C-00012dac] channel.c: DTMF end '#' received on SIP/peer1-3198a7-0002a61d, duration 89 ms
[2018-12-06 18:09:13] DTMF[158089][C-00012dac] channel.c: DTMF end passthrough '#' on SIP/peer1-3198a7-0002a61d

[2018-12-06 18:09:13] VERBOSE[158089][C-00012dac] file.c: <SIP/peer1-3198a7-0002a61d> Playing 'conf-invalidpin.alaw' (language 'uk')
[2018-12-06 18:09:17] VERBOSE[158089][C-00012dac] file.c: <SIP/peer1-3198a7-0002a61d> Playing 'conf-getpin.alaw' (language 'uk')
[2018-12-06 18:09:17] VERBOSE[158089][C-00012dac] file.c: <SIP/peer1-3198a7-0002a61d> Playing 'conf-invalidpin.alaw' (language 'uk')
[2018-12-06 18:09:17] VERBOSE[158089][C-00012dac] file.c: <SIP/peer1-3198a7-0002a61d> Playing 'conf-getpin.alaw' (language 'uk')
[2018-12-06 18:09:17] VERBOSE[158089][C-00012dac] file.c: <SIP/peer1-3198a7-0002a61d> Playing 'conf-invalidpin.alaw' (language 'uk')
[2018-12-06 18:09:17] VERBOSE[158089][C-00012dac] pbx.c: Spawn extension (10989-1143-routes, conf-11433, 4) exited non-zero on 'SIP/peer1-3198a7-0002a61d'
2

You need to Answer and give some time for the media flow to be established and strict RTP to lock on to the source, or otherwise some traffic will be lost at the beginning. You could also disable strict RTP support in rtp.conf but then you open yourself up to injection of media from other sources.

3

Thanks JCOLP. That makes sense. Will try, Thanks Again :slight_smile:

4

Changed the Dialplan to include answer for 4 seconds, but still no joy. Am I doing it right?

[2018-12-06 20:42:18] VERBOSE[100306][C-0001354f] pbx_builtins.c: Goto (10989-1143-routes,conf-11433,1)
[2018-12-06 20:42:18] VERBOSE[100306][C-0001354f] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:1] Answer("SIP/peer1-6347d-0002b15a", "4")
[2018-12-06 20:42:18] VERBOSE[100306][C-0001354f] res_rtp_asterisk.c: 0x7f68723310a0 -- Strict RTP switching to RTP target address xx.xx.xx.xx:22360 as source
[2018-12-06 20:42:19] VERBOSE[100306][C-0001354f] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:2] Noop("SIP/peer1-6347d-0002b15a", "2")
[2018-12-06 20:42:19] VERBOSE[100306][C-0001354f] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:3] Noop("SIP/peer1-6347d-0002b15a", "1")
[2018-12-06 20:42:19] VERBOSE[100306][C-0001354f] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:4] Confbridge("SIP/peer1-6347d-0002b15a", "11433_bridge,11433_bridge,11433_user")
[2018-12-06 20:42:19] VERBOSE[100306][C-0001354f] file.c: <SIP/peer1-6347d-0002b15a> Playing 'conf-getpin.alaw' (language 'uk')
[2018-12-06 20:42:22] DTMF[100306][C-0001354f] channel.c: DTMF begin '1' received on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:22] DTMF[100306][C-0001354f] channel.c: DTMF begin ignored '1' on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:23] DTMF[100306][C-0001354f] channel.c: DTMF end '1' received on SIP/peer1-6347d-0002b15a, duration 92 ms
[2018-12-06 20:42:23] DTMF[100306][C-0001354f] channel.c: DTMF end passthrough '1' on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:23] DTMF[100306][C-0001354f] channel.c: DTMF begin '6' received on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:23] DTMF[100306][C-0001354f] channel.c: DTMF begin ignored '6' on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:23] DTMF[100306][C-0001354f] channel.c: DTMF end '6' received on SIP/peer1-6347d-0002b15a, duration 95 ms
[2018-12-06 20:42:23] DTMF[100306][C-0001354f] channel.c: DTMF end passthrough '6' on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:23] VERBOSE[100306][C-0001354f] res_rtp_asterisk.c: 0x7f68723310a0 -- Strict RTP learning complete - Locking on source address xx.xx.xx.xx:22360
[2018-12-06 20:42:23] DTMF[100306][C-0001354f] channel.c: DTMF begin '4' received on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:23] DTMF[100306][C-0001354f] channel.c: DTMF begin ignored '4' on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF end '4' received on SIP/peer1-6347d-0002b15a, duration 99 ms
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF end passthrough '4' on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF end '4' received on SIP/peer1-6347d-0002b15a, duration 99 ms
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF end passthrough '4' on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF begin '5' received on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF begin ignored '5' on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF end '5' received on SIP/peer1-6347d-0002b15a, duration 91 ms
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF end passthrough '5' on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF begin '#' received on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF begin ignored '#' on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF end '#' received on SIP/peer1-6347d-0002b15a, duration 90 ms
[2018-12-06 20:42:24] DTMF[100306][C-0001354f] channel.c: DTMF end passthrough '#' on SIP/peer1-6347d-0002b15a
[2018-12-06 20:42:24] VERBOSE[100306][C-0001354f] file.c: <SIP/peer1-6347d-0002b15a> Playing 'conf-invalidpin.alaw' (language 'uk')
[2018-12-06 20:42:27] VERBOSE[100306][C-0001354f] file.c: <SIP/peer1-6347d-0002b15a> Playing 'conf-getpin.alaw' (language 'uk')
[2018-12-06 20:42:27] VERBOSE[100306][C-0001354f] file.c: <SIP/peer1-6347d-0002b15a> Playing 'conf-invalidpin.alaw' (language 'uk')
[2018-12-06 20:42:27] VERBOSE[100306][C-0001354f] file.c: <SIP/peer1-6347d-0002b15a> Playing 'conf-getpin.alaw' (language 'uk')
[2018-12-06 20:42:27] VERBOSE[100306][C-0001354f] file.c: <SIP/peer1-6347d-0002b15a> Playing 'conf-invalidpin.alaw' (language 'uk')
[2018-12-06 20:42:27] VERBOSE[100306][C-0001354f] pbx.c: Spawn extension (10989-1143-routes, conf-11433, 4) exited non-zero on 'SIP/peer1-6347d-0002b15a'
5

It’s still taking time to lock on. The lack of media flowing (doing Answer like that does not send media) is probably the cause. You can do a Playback(silence/1) or Playback(silence/2) before and see.

6

Grr, no better. We have RTP locked before DTMF now but still 1645# does not get recognized by confbridge app. I see digit 6 still has 2 more verbose lines than others.

[2018-12-06 21:14:41] VERBOSE[127670][C-00013683] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:1] Answer("SIP/peer1-a08c32-0002b248", "1")
[2018-12-06 21:14:41] VERBOSE[127670][C-00013683] res_rtp_asterisk.c: 0x7f68e65beef0 -- Strict RTP switching to RTP target address xx.xx.xx.xx:22568 as source
[2018-12-06 21:14:41] VERBOSE[127670][C-00013683] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:2] Playback("SIP/peer1-a08c32-0002b248", "silence/10")
[2018-12-06 21:14:41] VERBOSE[127670][C-00013683] file.c: <SIP/peer1-a08c32-0002b248> Playing 'silence/10.alaw' (language 'uk')
[2018-12-06 21:14:46] VERBOSE[127670][C-00013683] res_rtp_asterisk.c: 0x7f68e65beef0 -- Strict RTP learning complete - Locking on source address xx.xx.xx.xx:22568
[2018-12-06 21:14:51] VERBOSE[127670][C-00013683] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:3] Noop("SIP/peer1-a08c32-0002b248", "")
[2018-12-06 21:14:51] VERBOSE[127670][C-00013683] pbx_realtime.c: Executing [conf-11433@10989-1143-routes:4] Confbridge("SIP/peer1-a08c32-0002b248", "11433_bridge,11433_bridge,11433_user")
[2018-12-06 21:14:51] VERBOSE[127670][C-00013683] file.c: <SIP/peer1-a08c32-0002b248> Playing 'conf-getpin.alaw' (language 'uk')
[2018-12-06 21:14:55] DTMF[127670][C-00013683] channel.c: DTMF begin '1' received on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:55] DTMF[127670][C-00013683] channel.c: DTMF begin ignored '1' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:55] DTMF[127670][C-00013683] channel.c: DTMF end '1' received on SIP/peer1-a08c32-0002b248, duration 92 ms
[2018-12-06 21:14:55] DTMF[127670][C-00013683] channel.c: DTMF end passthrough '1' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:55] DTMF[127670][C-00013683] channel.c: DTMF begin '6' received on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:55] DTMF[127670][C-00013683] channel.c: DTMF begin ignored '6' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:55] DTMF[127670][C-00013683] channel.c: DTMF end '6' received on SIP/peer1-a08c32-0002b248, duration 92 ms
[2018-12-06 21:14:55] DTMF[127670][C-00013683] channel.c: DTMF end passthrough '6' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:55] DTMF[127670][C-00013683] channel.c: DTMF end '6' received on SIP/peer1-a08c32-0002b248, duration 92 ms
[2018-12-06 21:14:55] DTMF[127670][C-00013683] channel.c: DTMF end passthrough '6' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF begin '4' received on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF begin ignored '4' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end '4' received on SIP/peer1-a08c32-0002b248, duration 94 ms
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end passthrough '4' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end '4' received on SIP/peer1-a08c32-0002b248, duration 94 ms
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end passthrough '4' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF begin '5' received on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF begin ignored '5' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end '5' received on SIP/peer1-a08c32-0002b248, duration 86 ms
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end passthrough '5' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end '5' received on SIP/peer1-a08c32-0002b248, duration 86 ms
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end passthrough '5' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF begin '#' received on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF begin ignored '#' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end '#' received on SIP/peer1-a08c32-0002b248, duration 92 ms
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end passthrough '#' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] VERBOSE[127670][C-00013683] file.c: <SIP/peer1-a08c32-0002b248> Playing 'conf-invalidpin.alaw' (language 'uk')
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end '#' received on SIP/peer1-a08c32-0002b248, duration 92 ms
[2018-12-06 21:14:56] DTMF[127670][C-00013683] channel.c: DTMF end passthrough '#' on SIP/peer1-a08c32-0002b248
[2018-12-06 21:14:56] VERBOSE[127670][C-00013683] file.c: <SIP/peer1-a08c32-0002b248> Playing 'conf-getpin.alaw' (language 'uk')
[2018-12-06 21:14:59] VERBOSE[127670][C-00013683] file.c: <SIP/peer1-a08c32-0002b248> Playing 'conf-invalidpin.alaw' (language 'uk')
[2018-12-06 21:14:59] VERBOSE[127670][C-00013683] file.c: <SIP/peer1-a08c32-0002b248> Playing 'conf-getpin.alaw' (language 'uk')
[2018-12-06 21:14:59] VERBOSE[127670][C-00013683] file.c: <SIP/peer1-a08c32-0002b248> Playing 'conf-invalidpin.alaw' (language 'uk')
[2018-12-06 21:14:59] VERBOSE[127670][C-00013683] pbx.c: Spawn extension (10989-1143-routes, conf-11433, 4) exited non-zero on 'SIP/peer1-a08c32-0002b248'
7

I’d suggest providing the RTP trace itself then (rtp set debug on) so the traffic can be examined now that it is coming in completely.

8

Hi jcolp, hoping you can decipher this, nothing stands out to me.

9

I believe the problem is that in the middle of DTMF there is a single packet of audio, which is causing a duplicate end of the DTMF. You mention 13.24.1 in the subject of this, but that version doesn’t exist. What version are you actually using? If it’s the release candidate please try the current release (13.21.1) to see if it is a regression there.

10

sorry using 13.24.0.rcl. jumped from 11.21, then to 13.21.cert3. Had asterisk crashing with WebRTC on this version so upgraded to 13.24.0.rcl and resolved crashes. Perhaps if I downgrade to 13.23 may be better middle ground? thanks

11

It’s a data point to see if there is a regression in the release candidates.

12

Great, will try 13.23.1 and let you know.

13

Downgrade to 13.23.1 done the trick. Many thanks JCOLP.

14

Please file an issue on the issue tracker[1] with this information.

[1] https://issues.asterisk.org/jira

15

Done. ASTERISK-28200

Thanks.