[asterisk-bugs] [JIRA] (ASTERISK-25919) Duplicate DTMF events in ARI

Richard Frith-Macdonald (JIRA) noreply at issues.asterisk.org
Fri May 15 10:10:27 CDT 2020 

    [ https://issues.asterisk.org/jira/browse/ASTERISK-25919?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=250784#comment-250784 ] 

Richard Frith-Macdonald commented on ASTERISK-25919:
----------------------------------------------------

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"}'



> Duplicate DTMF events in ARI
> ----------------------------
>
>                 Key: ASTERISK-25919
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-25919
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Channels/General
>    Affects Versions: 13.7.2, 13.8.0
>         Environment: Amazon Linux EC2 t2.micro test setup
>            Reporter: Kristan McDonald
>            Severity: Minor
>         Attachments: DTMF1.log, DTMF1.log, DTMF2.log, DTMF2.log
>
>
> 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.



--
This message was sent by Atlassian JIRA
(v6.2#6252)

More information about the asterisk-bugs mailing list