[asterisk-bugs] [JIRA] (ASTERISK-25919) Duplicate DTMF events in ARI
Oded Arbel (JIRA)
noreply at issues.asterisk.org
Mon Jan 7 06:21:47 CST 2019
[ https://issues.asterisk.org/jira/browse/ASTERISK-25919?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=245916#comment-245916 ]
Oded Arbel commented on ASTERISK-25919:
---------------------------------------
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:
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.kaller.io-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.kaller.io-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.kaller.io-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.kaller.io-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.kaller.io-00000002
[Jan 7 10:52:42] DTMF[15192][C-00000003]: channel.c:4130 __ast_read: DTMF begin ignored '8' on SIP/sip.kaller.io-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.kaller.io-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.kaller.io-00000002",
"state": "Up",
"caller": {
"name": "",
"number": "972539188408"
},
"connected": {
"name": "",
"number": ""
},
"accountcode": "",
"dialplan": {
"context": "cloudonix-appcore",
"exten": "972525831995",
"priority": 2
},
"creationtime": "2019-01-07T10:52:27.966+0000",
"language": "en"
},
"asterisk_id": "06:e1:8f:62:ab:3e",
"application": "appcore"
}
<--- 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.kaller.io-00000002",
"state": "Up",
"caller": {
"name": "",
"number": "972539188408"
},
"connected": {
"name": "",
"number": ""
},
"accountcode": "",
"dialplan": {
"context": "cloudonix-appcore",
"exten": "972525831995",
"priority": 2
},
"creationtime": "2019-01-07T10:52:27.966+0000",
"language": "en"
},
"asterisk_id": "06:e1:8f:62:ab:3e",
"application": "appcore"
}
[Jan 7 10:52:42] DTMF[15192][C-00000003]: channel.c:4160 __ast_read: DTMF end emulation of '7' queued on SIP/sip.kaller.io-00000002
[Jan 7 10:52:42] DTMF[15192][C-00000003]: channel.c:4040 __ast_read: DTMF end '8' received on SIP/sip.kaller.io-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.kaller.io-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.kaller.io-00000002",
"state": "Up",
"caller": {
"name": "",
"number": "972539188408"
},
"connected": {
"name": "",
"number": ""
},
"accountcode": "",
"dialplan": {
"context": "cloudonix-appcore",
"exten": "972525831995",
"priority": 2
},
"creationtime": "2019-01-07T10:52:27.966+0000",
"language": "en"
},
"asterisk_id": "06:e1:8f:62:ab:3e",
"application": "appcore"
}
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.
> 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