Duplicate DTMF events in ARI

1

Hi,

I’m troubleshooting an issue with duplicate DTMF being sent to my ARI application.

DTMF is coming into pjsip via RFC 2833 ok, confirmed via packet capture.

The issue seems to be when tones are close together. When spaced out, the logs say :

DTMF begin '#' received on PJSIP/dev-endpoint-0000000c
DTMF begin passthrough '#' on PJSIP/dev-endpoint-0000000c
DTMF end '#' received on PJSIP/dev-endpoint-0000000c, duration 100 ms
DTMF end accepted with begin '#' on PJSIP/dev-endpoint-0000000c
DTMF end '#' detected to have actual duration 1 on the wire, emulation will be triggered on PJSIP/dev-endpoint-0000000c
DTMF end '#' has duration 1 but want minimum 80, emulating on PJSIP/dev-endpoint-0000000c
DTMF end emulation of '#' queued on PJSIP/dev-endpoint-0000000c

but when the tones are close together, the second says :

DTMF begin '#' received on PJSIP/dev-endpoint-0000000c
DTMF begin ignored '#' on PJSIP/dev-endpoint-0000000c
DTMF end '#' received on PJSIP/dev-endpoint-0000000c, duration 100 ms
DTMF end '#' received on PJSIP/dev-endpoint-0000000c, duration 100 ms
DTMF begin emulation of '#' with duration 100 queued on PJSIP/dev-endpoint-0000000c
DTMF end emulation of '#' queued on PJSIP/dev-endpoint-0000000c

And this seems to result in the tone being sent twice to the ARI (I get TWO events for the same digits raised from ChannelDtmfReceived ).

Anyone any clues as to where to go next? This is driving me mental!

Thanks!

2

What version of Asterisk, what does the exact “rtp set debug on” output provide, and what was actually pressed?

3

13.7.2, built from source.

RTP and DTMF logging on. Correct behaviour - pressed 1, got 1 in the ARI :

Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005242, ts 030240, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005242, ts 030240, len 000004, mark 1, event 00000001, end 0, duration 00000)
[Apr 13 13:01:32] DTMF[13085][C-00000012]: channel.c:4030 __ast_read: DTMF begin '1' received on PJSIP/dev-endpoint-00000012
[Apr 13 13:01:32] DTMF[13085][C-00000012]: channel.c:4041 __ast_read: DTMF begin passthrough '1' on PJSIP/dev-endpoint-00000012
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005243, ts 030240, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005243, ts 030240, len 000004, mark 0, event 00000001, end 0, duration 00000)
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005244, ts 030240, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005244, ts 030240, len 000004, mark 0, event 00000001, end 0, duration 00000)
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005245, ts 030240, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005245, ts 030240, len 000004, mark 0, event 00000001, end 1, duration 00800)
[Apr 13 13:01:32] DTMF[13085][C-00000012]: channel.c:3944 __ast_read: DTMF end '1' received on PJSIP/dev-endpoint-00000012, duration 100 ms
[Apr 13 13:01:32] DTMF[13085][C-00000012]: channel.c:3985 __ast_read: DTMF end accepted with begin '1' on PJSIP/dev-endpoint-00000012
[Apr 13 13:01:32] DTMF[13085][C-00000012]: channel.c:4000 __ast_read: DTMF end '1' detected to have actual duration 2 on the wire, emulation will be triggered on PJSIP/dev-endpoint-00000012
[Apr 13 13:01:32] DTMF[13085][C-00000012]: channel.c:4007 __ast_read: DTMF end '1' has duration 2 but want minimum 80, emulating on PJSIP/dev-endpoint-00000012
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005245, ts 030240, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005245, ts 030240, len 000004, mark 0, event 00000001, end 1, duration 00800)
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005245, ts 030240, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005245, ts 030240, len 000004, mark 0, event 00000001, end 1, duration 00800)
Got  RTP packet from    194.145.190.143:19808 (type 08, seq 005246, ts 039360, len 000160)
[Apr 13 13:01:33] DTMF[13085][C-00000012]: channel.c:4108 __ast_read: DTMF end emulation of '1' queued on PJSIP/dev-endpoint-00000012

Bad behaviour, pressed 4 then 5, got 4, 5, 5 in the ARI :

Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005348, ts 063680, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005348, ts 063680, len 000004, mark 1, event 00000004, end 0, duration 00000)
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:4030 __ast_read: DTMF begin '4' received on PJSIP/dev-endpoint-00000012
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:4041 __ast_read: DTMF begin passthrough '4' on PJSIP/dev-endpoint-00000012
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005349, ts 063680, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005349, ts 063680, len 000004, mark 0, event 00000004, end 0, duration 00000)
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005350, ts 063680, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005350, ts 063680, len 000004, mark 0, event 00000004, end 0, duration 00000)
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005351, ts 063680, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005351, ts 063680, len 000004, mark 0, event 00000004, end 1, duration 00800)
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:3944 __ast_read: DTMF end '4' received on PJSIP/dev-endpoint-00000012, duration 100 ms
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:3985 __ast_read: DTMF end accepted with begin '4' on PJSIP/dev-endpoint-00000012
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:4000 __ast_read: DTMF end '4' detected to have actual duration 1 on the wire, emulation will be triggered on PJSIP/dev-endpoint-00000012
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:4007 __ast_read: DTMF end '4' has duration 1 but want minimum 80, emulating on PJSIP/dev-endpoint-00000012
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005351, ts 063680, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005351, ts 063680, len 000004, mark 0, event 00000004, end 1, duration 00800)
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005351, ts 063680, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005351, ts 063680, len 000004, mark 0, event 00000004, end 1, duration 00800)
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005352, ts 064640, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005352, ts 064640, len 000004, mark 1, event 00000005, end 0, duration 00000)
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:4030 __ast_read: DTMF begin '5' received on PJSIP/dev-endpoint-00000012
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:4034 __ast_read: DTMF begin ignored '5' on PJSIP/dev-endpoint-00000012
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005353, ts 064640, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005353, ts 064640, len 000004, mark 0, event 00000005, end 0, duration 00000)
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:4064 __ast_read: DTMF end emulation of '4' queued on PJSIP/dev-endpoint-00000012
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005354, ts 064640, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005354, ts 064640, len 000004, mark 0, event 00000005, end 0, duration 00000)
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005355, ts 064640, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005355, ts 064640, len 000004, mark 0, event 00000005, end 1, duration 00800)
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:3944 __ast_read: DTMF end '5' received on PJSIP/dev-endpoint-00000012, duration 100 ms
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:3944 __ast_read: DTMF end '5' received on PJSIP/dev-endpoint-00000012, duration 100 ms
[Apr 13 13:01:36] DTMF[13085][C-00000012]: channel.c:3971 __ast_read: DTMF begin emulation of '5' with duration 100 queued on PJSIP/dev-endpoint-00000012
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005355, ts 064640, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005355, ts 064640, len 000004, mark 0, event 00000005, end 1, duration 00800)
Got  RTP packet from    194.145.190.143:19808 (type 101, seq 005355, ts 064640, len 000004)
Got  RTP RFC2833 from   194.145.190.143:19808 (type 101, seq 005355, ts 064640, len 000004, mark 0, event 00000005, end 1, duration 00800)
Got  RTP packet from    194.145.190.143:19808 (type 08, seq 005356, ts 074080, len 000160)
[Apr 13 13:01:37] DTMF[13085][C-00000012]: channel.c:4108 __ast_read: DTMF end emulation of '5' queued on PJSIP/dev-endpoint-00000012
4

Please open an issue on the issue tracker[1] with the description above and attach the logs. It appears as though the underlying event is getting raised twice and does not take into account the emulation scenario (we ensure DTMF has a minimum length and to do so we have to emulate it).

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

5

Done, https://issues.asterisk.org/jira/browse/ASTERISK-25919

Thanks for your help.

1 Like