[Home]

Summary:ASTERISK-25919: Duplicate DTMF events in ARI
Reporter:Kristan McDonald (Kristan)Labels:
Date Opened:2016-04-13 11:03:00Date Closed:
Priority:MinorRegression?
Status:Open/NewComponents:Channels/General
Versions:13.7.2 13.8.0 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Amazon Linux EC2 t2.micro test setupAttachments:( 0) DTMF1.log
( 1) DTMF1.log
( 2) DTMF2.log
( 3) DTMF2.log
Description:Using the test node.js application code from :

https://wiki.asterisk.org/wiki/display/AST/ARI+and+Channels%3A+Handling+DTMF

If two DTMF tones are received close together, the second tone is sent TWICE to the ARI interface.

RTP & DTMF logs are attached.

See DTMF1.log for correct processing - 1 pressed on handset, 1 sent to ARI.

See DTMF2.log for incorrect processing - 4 then 5 pressed on handset, 4, 5, 5 sent to ARI.

Also see community support request :

https://community.asterisk.org/t/duplicate-dtmf-events-in-ari/66368

I can reproduce if required.
Comments:By: Asterisk Team (asteriskteam) 2016-04-13 11:03:00.983-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: Rusty Newton (rnewton) 2016-04-14 08:42:53.164-0500

[~Kristan] you attached your logs, but incorrectly marked them as a code contribution. That means they will not show up on the issue until you have a signed submission agreement on file.

You should delete your attachments and correctly re-attach them as a non-contribution. Thanks!
By: Kristan McDonald (Kristan) 2016-04-14 08:53:21.943-0500

Apologies, files uploaded correctly now!
By: Kristan McDonald (Kristan) 2016-05-04 05:36:08.507-0500

As a workaround:
In channels.c I've added a check to prevent send_dtmf_end_event being called in the __ast_read function if the seqno of the frame is 0. This has the effect of stopping the second, duplicate tone being published into stasis.

I'm pretty certain this is definitely not the correct fix, I think it's more related to the way the DTMF is queued whilst a previous tone is being emulated, but my asterisk skills don't go as far as to be able to help there..
By: Oded Arbel (guss77) 2019-01-07 06:21:42.304-0600

I have the same issue with Asterisk 14.7.2 (yes, old, I know - planning to upgrade but after reviewing the code, I believe this is still a problem with the current version).

Our reproduction is as follows:
1. A DTMF begin event is received and detected.
2. The relevant DTMF end event is received, but (possibly due to delays in the network) is received less than option_dtmfminduration ms after the begin event, and __ast_read() decides to start emulation.
3. A new DTMF begin event is received, before emulation of the previous DTMF digit has ended, and is thus ignored.
4. The relevant DTMF end event is received, but because we are still emulating the previous digit, gets deferred - but after the ChannelDtmfReceived was already sent.
5. The deferred DTMF end event gets received again, and ChannelDtmfReceived is sent again.

Here is a console output with DTMF, RTP and ARI debug enabled:

{noformat}
Got  RTP RFC2833 from   18.205.100.13:39730 (type 96, seq 027847, ts 2891171671, len 000004, mark 0, event 00000007, end 1, duration 01920)
[Jan  7 10:52:42] DTMF[15192][C-00000003]: channel.c:4040 __ast_read: DTMF end '7' received on SIP/sip.domain.com-00000002, duration 240 ms
[Jan  7 10:52:42] DTMF[15192][C-00000003]: channel.c:4081 __ast_read: DTMF end accepted with begin '7' on SIP/sip.domain.com-00000002
[Jan  7 10:52:42] DTMF[15192][C-00000003]: channel.c:4096 __ast_read: DTMF end '7' detected to have actual duration 0 on the wire, emulation will be triggered on SIP/sip.domain.com-00000002
[Jan  7 10:52:42] DTMF[15192][C-00000003]: channel.c:4103 __ast_read: DTMF end '7' has duration 0 but want minimum 7, emulating on SIP/sip.domain.com-00000002
Got  RTP packet from    18.205.100.13:39730 (type 96, seq 027848, ts 2891171671, len 000004)
Got  RTP RFC2833 from   18.205.100.13:39730 (type 96, seq 027848, ts 2891171671, len 000004, mark 0, event 00000007, end 1, duration 01920)
Got  RTP packet from    18.205.100.13:39730 (type 96, seq 027849, ts 2891171671, len 000004)
Got  RTP RFC2833 from   18.205.100.13:39730 (type 96, seq 027849, ts 2891171671, len 000004, mark 0, event 00000007, end 1, duration 01920)
... more RTP packets...
Got  RTP RFC2833 from   18.205.100.13:39730 (type 96, seq 027885, ts 2891208151, len 000004, mark 1, event 00000008, end 0, duration 00960)
[Jan  7 10:52:42] DTMF[15192][C-00000003]: channel.c:4126 __ast_read: DTMF begin '8' received on SIP/sip.domain.com-00000002
[Jan  7 10:52:42] DTMF[15192][C-00000003]: channel.c:4130 __ast_read: DTMF begin ignored '8' on SIP/sip.domain.com-00000002
Got  RTP packet from    18.205.100.13:39730 (type 96, seq 027886, ts 2891208151, len 000004)
Got  RTP RFC2833 from   18.205.100.13:39730 (type 96, seq 027886, ts 2891208151, len 000004, mark 0, event 00000008, end 1, duration 01920)
[Jan  7 10:52:42] DTMF[15192][C-00000003]: channel.c:4040 __ast_read: DTMF end '8' received on SIP/sip.domain.com-00000002, duration 240 ms
<--- Sending ARI event to 172.17.0.2:59214 --->
{
 "type": "ChannelDtmfReceived",
 "timestamp": "2019-01-07T10:52:42.588+0000",
 "digit": "7",
 "duration_ms": 240,
 "channel": {
   "id": "1546858347.4",
   "name": "SIP/sip.domain.com-00000002",
   "state": "Up",
   "caller": {
     "name": "",
     "number": "972539188408"
   },
   "connected": {
     "name": "",
     "number": ""
   },
   "accountcode": "",
   "dialplan": {
     "context": "stasis-app",
     "exten": "972541234567",
     "priority": 2
   },
   "creationtime": "2019-01-07T10:52:27.966+0000",
   "language": "en"
 },
 "asterisk_id": "06:e1:8f:62:ab:3e",
 "application": "StasisApp"
}
<--- Sending ARI event to 172.17.0.2:59214 --->
{
 "type": "ChannelDtmfReceived",
 "timestamp": "2019-01-07T10:52:42.588+0000",
 "digit": "8",
 "duration_ms": 240,
 "channel": {
   "id": "1546858347.4",
   "name": "SIP/sip.domain.com-00000002",
   "state": "Up",
   "caller": {
     "name": "",
     "number": "972539188408"
   },
   "connected": {
     "name": "",
     "number": ""
   },
   "accountcode": "",
   "dialplan": {
     "context": "stasis-app",
     "exten": "972541234567",
     "priority": 2
   },
   "creationtime": "2019-01-07T10:52:27.966+0000",
   "language": "en"
 },
 "asterisk_id": "06:e1:8f:62:ab:3e",
 "application": "StasisApp"
}
[Jan  7 10:52:42] DTMF[15192][C-00000003]: channel.c:4160 __ast_read: DTMF end emulation of '7' queued on SIP/sip.domain.com-00000002
[Jan  7 10:52:42] DTMF[15192][C-00000003]: channel.c:4040 __ast_read: DTMF end '8' received on SIP/sip.domain.com-00000002, duration 240 ms
[Jan  7 10:52:42] DTMF[15192][C-00000003]: channel.c:4067 __ast_read: DTMF begin emulation of '8' with duration 240 queued on SIP/sip.domain.com-00000002
Got  RTP packet from    18.205.100.13:39730 (type 96, seq 027887, ts 2891208151, len 000004)
Got  RTP RFC2833 from   18.205.100.13:39730 (type 96, seq 027887, ts 2891208151, len 000004, mark 0, event 00000008, end 1, duration 01920)
Got  RTP packet from    18.205.100.13:39730 (type 96, seq 027888, ts 2891208151, len 000004)
Got  RTP RFC2833 from   18.205.100.13:39730 (type 96, seq 027888, ts 2891208151, len 000004, mark 0, event 00000008, end 1, duration 01920)
... more RTP packets ...
<--- Sending ARI event to 172.17.0.2:59214 --->
{
 "type": "ChannelDtmfReceived",
 "timestamp": "2019-01-07T10:52:42.663+0000",
 "digit": "8",
 "duration_ms": 240,
 "channel": {
   "id": "1546858347.4",
   "name": "SIP/sip.domain.com-00000002",
   "state": "Up",
   "caller": {
     "name": "",
     "number": "972539188408"
   },
   "connected": {
     "name": "",
     "number": ""
   },
   "accountcode": "",
   "dialplan": {
     "context": "stasis-app",
     "exten": "972541234567",
     "priority": 2
   },
   "creationtime": "2019-01-07T10:52:27.966+0000",
   "language": "en"
 },
 "asterisk_id": "06:e1:8f:62:ab:3e",
 "application": "StasisApp"
}
{noformat}

I'm working on testing patches, but @Kristan's approach seems like it could work - when Asterisk defers the packet, it copies its payload but not its sequence number so preventing send_dtmf_end_event() on deferred packets, identified by an incomplete copy, would appear to work.

Ideally, I think a better solution is to call send_dtmf_end_event() at the end of __ast_read()'s AST_FRAME_DTMF_END processing, and only if the frame was not reset by the defering process or its frametype has not been changed to AST_FRAME_DTMF_BEGIN by the else part on the (ast_tvdiff_ms(ast_tvnow(), *ast_channel_dtmf_tv(chan)) < AST_MIN_DTMF_GAP) condition.
By: Richard Frith-Macdonald (richardfm) 2020-05-15 10:10:23.517-0500

I'm getting what seems like this error in asterisk 17 ... when a user is asked to enter a relatively long sequence of digits we are quite often (about one in five times, which makes this a big issue) getting the later digits duplicated.

Below is an example log of the asterisk dtmf events and corresponding ARI events (I can supply an rtp packet dump if necessary) for a case where someone entered 1234567# but our application read back 1234556677 to them!

May 13 14:17:44] DTMF[150759][C-00000239] channel.c: DTMF begin ‘1’ received on PJSIP/Voxbone-000002b6
[May 13 14:17:44] DTMF[150759][C-00000239] channel.c: DTMF begin ignored ‘1’ on PJSIP/Voxbone-000002b6
[May 13 14:17:44] DTMF[150759][C-00000239] channel.c: DTMF end ‘1’ received on PJSIP/Voxbone-000002b6, duration 400 ms
[May 13 14:17:44] DTMF[150759][C-00000239] channel.c: DTMF end passthrough ‘1’ on PJSIP/Voxbone-000002b6
[May 13 14:17:44] DTMF[150759][C-00000239] channel.c: DTMF begin ‘2’ received on PJSIP/Voxbone-000002b6
[May 13 14:17:44] DTMF[150759][C-00000239] channel.c: DTMF begin ignored ‘2’ on PJSIP/Voxbone-000002b6
[May 13 14:17:45] DTMF[150759][C-00000239] channel.c: DTMF end ‘2’ received on PJSIP/Voxbone-000002b6, duration 360 ms
[May 13 14:17:45] DTMF[150759][C-00000239] channel.c: DTMF end passthrough ‘2’ on PJSIP/Voxbone-000002b6
[May 13 14:17:45] DTMF[150759][C-00000239] channel.c: DTMF begin ‘3’ received on PJSIP/Voxbone-000002b6
[May 13 14:17:45] DTMF[150759][C-00000239] channel.c: DTMF begin ignored ‘3’ on PJSIP/Voxbone-000002b6
[May 13 14:17:45] DTMF[150759][C-00000239] channel.c: DTMF end ‘3’ received on PJSIP/Voxbone-000002b6, duration 440 ms
[May 13 14:17:45] DTMF[150759][C-00000239] channel.c: DTMF end passthrough ‘3’ on PJSIP/Voxbone-000002b6
[May 13 14:17:46] DTMF[150759][C-00000239] channel.c: DTMF begin ‘4’ received on PJSIP/Voxbone-000002b6
[May 13 14:17:46] DTMF[150759][C-00000239] channel.c: DTMF begin ignored ‘4’ on PJSIP/Voxbone-000002b6
[May 13 14:17:46] DTMF[150759][C-00000239] channel.c: DTMF end ‘4’ received on PJSIP/Voxbone-000002b6, duration 355 ms
[May 13 14:17:46] DTMF[150759][C-00000239] channel.c: DTMF begin emulation of ‘4’ with duration 355 queued on PJSIP/Voxbone-000002b6
[May 13 14:17:47] DTMF[150759][C-00000239] channel.c: DTMF begin ‘5’ received on PJSIP/Voxbone-000002b6
[May 13 14:17:47] DTMF[150759][C-00000239] channel.c: DTMF begin ignored ‘5’ on PJSIP/Voxbone-000002b6
[May 13 14:17:47] DTMF[150759][C-00000239] channel.c: DTMF end ‘5’ received on PJSIP/Voxbone-000002b6, duration 320 ms
[May 13 14:17:47] DTMF[150759][C-00000239] channel.c: DTMF end emulation of ‘4’ queued on PJSIP/Voxbone-000002b6
[May 13 14:17:47] DTMF[150759][C-00000239] channel.c: DTMF end ‘5’ received on PJSIP/Voxbone-000002b6, duration 320 ms
[May 13 14:17:47] DTMF[150759][C-00000239] channel.c: DTMF begin emulation of ‘5’ with duration 320 queued on PJSIP/Voxbone-000002b6
[May 13 14:17:47] DTMF[150759][C-00000239] channel.c: DTMF begin ‘6’ received on PJSIP/Voxbone-000002b6
[May 13 14:17:47] DTMF[150759][C-00000239] channel.c: DTMF begin ignored ‘6’ on PJSIP/Voxbone-000002b6
[May 13 14:17:48] DTMF[150759][C-00000239] channel.c: DTMF end ‘6’ received on PJSIP/Voxbone-000002b6, duration 345 ms
[May 13 14:17:48] DTMF[150759][C-00000239] channel.c: DTMF end emulation of ‘5’ queued on PJSIP/Voxbone-000002b6
[May 13 14:17:48] DTMF[150759][C-00000239] channel.c: DTMF end ‘6’ received on PJSIP/Voxbone-000002b6, duration 345 ms
[May 13 14:17:48] DTMF[150759][C-00000239] channel.c: DTMF begin emulation of ‘6’ with duration 345 queued on PJSIP/Voxbone-000002b6
[May 13 14:17:48] DTMF[150759][C-00000239] channel.c: DTMF begin ‘7’ received on PJSIP/Voxbone-000002b6
[May 13 14:17:48] DTMF[150759][C-00000239] channel.c: DTMF begin ignored ‘7’ on PJSIP/Voxbone-000002b6
[May 13 14:17:48] DTMF[150759][C-00000239] channel.c: DTMF end ‘7’ received on PJSIP/Voxbone-000002b6, duration 390 ms
[May 13 14:17:48] DTMF[150759][C-00000239] channel.c: DTMF end emulation of ‘6’ queued on PJSIP/Voxbone-000002b6
[May 13 14:17:48] DTMF[150759][C-00000239] channel.c: DTMF end ‘7’ received on PJSIP/Voxbone-000002b6, duration 390 ms
[May 13 14:17:48] DTMF[150759][C-00000239] channel.c: DTMF begin emulation of ‘7’ with duration 390 queued on PJSIP/Voxbone-000002b6
[May 13 14:17:49] DTMF[150759][C-00000239] channel.c: DTMF begin ‘#’ received on PJSIP/Voxbone-000002b6
[May 13 14:17:49] DTMF[150759][C-00000239] channel.c: DTMF begin ignored ‘#’ on PJSIP/Voxbone-000002b6
[May 13 14:17:49] DTMF[150759][C-00000239] channel.c: DTMF end ‘#’ received on PJSIP/Voxbone-000002b6, duration 345 ms
[May 13 14:17:49] DTMF[150759][C-00000239] channel.c: DTMF end emulation of ‘7’ queued on PJSIP/Voxbone-000002b6
[May 13 14:17:49] DTMF[150759][C-00000239] channel.c: DTMF end ‘#’ received on PJSIP/Voxbone-000002b6, duration 345 ms
[May 13 14:17:49] DTMF[150759][C-00000239] channel.c: DTMF end passthrough ‘#’ on PJSIP/Voxbone-000002b6

'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:44.584+0100","digit":"1","duration_ms":400,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'
'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:45.264+0100","digit":"2","duration_ms":360,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'
'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:45.984+0100","digit":"3","duration_ms":440,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'
'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:46.704+0100","digit":"4","duration_ms":355,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'
'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:47.324+0100","digit":"5","duration_ms":320,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'
'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:47.369+0100","digit":"5","duration_ms":320,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'
'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:48.004+0100","digit":"6","duration_ms":345,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'
'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:48.049+0100","digit":"6","duration_ms":345,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'
'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:48.704+0100","digit":"7","duration_ms":390,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'
'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:48.749+0100","digit":"7","duration_ms":390,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'
'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:49.404+0100","digit":"#","duration_ms":345,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'
'{"type":"ChannelDtmfReceived","timestamp":"2020-05-13T14:17:49.449+0100","digit":"#","duration_ms":345,"channel":{"id":"1589375858.1260","name":"PJSIP/Voxbone-000002b6","state":"Up","caller":{"name":"","number":"4477********"},"connected":{"name":"","number":""},"accountcode":"","dialplan":{"context":"Voxbone","exten":"4412********","priority":1,"app_name":"Stasis","app_data":"MyApp"},"creationtime":"2020-05-13T14:17:38.963+0100","language":"en"},"asterisk_id":"4c:d9:8f:45:b3:93","application":"MyApp"}'


By: Richard Frith-Macdonald (richardfm) 2020-05-15 10:18:02.732-0500

NB. we have seen what looks like the same problem with two different SIP providers, so it may be quite a common issue.