We have an IVR system based on ARI (version 13, with FreePBX 13). I have noticed that when a users presses star (*) the event is sent to the ARI application at about one second delay. I assume Asterisk is waiting for a feature code, and only after confirming the user did not used one, it passes the event to ARI.
Is there a way to disable this behavior? We need the ARI application to respond to a star DTMF immediately.
Thanks,
Eyal Hasson.
If the channel is directly in the ARI application then it wouldn’t be looking for the *. Can you provide the console output?
Bellow is the console output. The star digit has been pressed just before the “playback stopped…” log line.
An interesting point I noticed, that this happens only for a call coming from the external trunk. A call from a SIP phone directly connected to the server does not have this problem.
[2017-06-01 16:33:09] VERBOSE[30148] asterisk.c: Remote UNIX connection
[2017-06-01 16:33:13] VERBOSE[30179][C-00000072] netsock2.c: Using SIP RTP TOS bits 184
[2017-06-01 16:33:13] VERBOSE[30179][C-00000072] netsock2.c: Using SIP RTP CoS mark 5
[2017-06-01 16:33:13] VERBOSE[16831][C-00000072] pbx.c: Executing [1001@from-internal:1] Gosub(“SIP/MainSystemTrunk-00000072”, “StartKhlListen,start,1(from-internal,1001)”) in new stack
[2017-06-01 16:33:13] VERBOSE[16831][C-00000072] pbx.c: Executing [start@StartKhlListen:1] NoOp(“SIP/MainSystemTrunk-00000072”, “entering from-internal / 1001 from 0732201211”) in new stack
[2017-06-01 16:33:13] VERBOSE[16831][C-00000072] pbx.c: Executing [start@StartKhlListen:2] Set(“SIP/MainSystemTrunk-00000072”, “CONTEXT2=from-internal”) in new stack
[2017-06-01 16:33:13] VERBOSE[16831][C-00000072] pbx.c: Executing [start@StartKhlListen:3] Set(“SIP/MainSystemTrunk-00000072”, “EXTEN2=1001”) in new stack
[2017-06-01 16:33:13] VERBOSE[16831][C-00000072] pbx.c: Executing [start@StartKhlListen:4] Set(“SIP/MainSystemTrunk-00000072”, “AGC(rx)=28000”) in new stack
[2017-06-01 16:33:13] VERBOSE[16831][C-00000072] pbx.c: Executing [start@StartKhlListen:5] Set(“SIP/MainSystemTrunk-00000072”, “AGC(tx)=28000”) in new stack
[2017-06-01 16:33:13] VERBOSE[16831][C-00000072] pbx.c: Executing [start@StartKhlListen:6] Set(“SIP/MainSystemTrunk-00000072”, “DENOISE(rx)=on”) in new stack
[2017-06-01 16:33:13] VERBOSE[16831][C-00000072] pbx.c: Executing [start@StartKhlListen:7] Set(“SIP/MainSystemTrunk-00000072”, “DENOISE(tx)=on”) in new stack
[2017-06-01 16:33:13] VERBOSE[16831][C-00000072] pbx.c: Executing [start@StartKhlListen:8] Set(“SIP/MainSystemTrunk-00000072”, “CODEC=(g722)”) in new stack
[2017-06-01 16:33:13] VERBOSE[16831][C-00000072] pbx.c: Executing [start@StartKhlListen:9] Stasis(“SIP/MainSystemTrunk-00000072”, “KhlSystemBackupApp”) in new stack
[2017-06-01 16:33:13] VERBOSE[16831][C-00000072] file.c: <SIP/MainSystemTrunk-00000072> Playing ‘…/…/…/…/home/asterisk/ToraPrompts/HEBREW.SHUSHAN/ulaw/Start.ulaw’ (language ‘en’)
[2017-06-01 16:33:17] VERBOSE[16831][C-00000072] file.c: <SIP/MainSystemTrunk-00000072> Playing ‘…/…/…/…/home/asterisk/ToraPrompts/Hebrew/ulaw/Special3.ulaw’ (language ‘en’)
[2017-06-01 16:33:21] NOTICE[16831][C-00000072] res_stasis_playback.c: 1496323993.128: Playback stopped for sound:…/…/…/…/home/asterisk/ToraPrompts/Hebrew/ulaw/Special3
[2017-06-01 16:33:22] VERBOSE[16831][C-00000072] file.c: <SIP/MainSystemTrunk-00000072> Playing ‘…/…/…/…/home/asterisk/ToraPrompts/Hebrew/ulaw/ChannelsApp.ulaw’ (language ‘en’)
[2017-06-01 16:33:26] VERBOSE[16831][C-00000072] file.c: <SIP/MainSystemTrunk-00000072> Playing ‘…/…/…/…/home/asterisk/ToraPrompts/HEBREW.SHUSHAN/ulaw/Hebrew.ulaw’ (language ‘en’)
What is the output of “rtp set debug on” as well? That will show when the digit was actually received. You can also enabling DTMF logging in logger.conf which will show when Asterisk recognizes it.
Bellow is the relevant debug log with dtmf logging:
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:16000 (type 09, seq 033731, ts 013784, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.42:10316 (type 101, seq 010083, ts 93763233, len 000004)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.0.42:10316 (type 101, seq 010083, ts 93763233, len 000004, mark 1, event 0000000a, end 0, duration 00000)
[2017-06-01 17:18:13] DEBUG[19583][C-00000005] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4)
[2017-06-01 17:18:13] DTMF[19583][C-00000005] channel.c: DTMF begin ‘’ received on SIP/9111-00000007
[2017-06-01 17:18:13] DTMF[19583][C-00000005] channel.c: DTMF begin passthrough '’ on SIP/9111-00000007
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.41:16000 (type 09, seq 021252, ts 016320, len 000160)
[2017-06-01 17:18:13] VERBOSE[19586][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:19190 (type 09, seq 001953, ts 015128, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.42:10316 (type 00, seq 030362, ts 015112, len 000160)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:16000 (type 09, seq 033732, ts 013944, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.42:10316 (type 101, seq 010084, ts 93763233, len 000004)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.0.42:10316 (type 101, seq 010084, ts 93763233, len 000004, mark 0, event 0000000a, end 0, duration 00160)
[2017-06-01 17:18:13] DEBUG[19583][C-00000005] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.41:16000 (type 09, seq 021253, ts 016480, len 000160)
[2017-06-01 17:18:13] VERBOSE[19586][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:19190 (type 09, seq 001954, ts 015288, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.42:10316 (type 00, seq 030363, ts 015272, len 000160)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:16000 (type 09, seq 033733, ts 014104, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.42:10316 (type 101, seq 010085, ts 93763233, len 000004)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.0.42:10316 (type 101, seq 010085, ts 93763233, len 000004, mark 0, event 0000000a, end 0, duration 00320)
[2017-06-01 17:18:13] DEBUG[19583][C-00000005] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.41:16000 (type 09, seq 021254, ts 016640, len 000160)
[2017-06-01 17:18:13] VERBOSE[19586][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:19190 (type 09, seq 001955, ts 015448, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.42:10316 (type 00, seq 030364, ts 015432, len 000160)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:16000 (type 09, seq 033734, ts 014264, len 000160)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.41:16000 (type 09, seq 021255, ts 016800, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.42:10316 (type 101, seq 010086, ts 93763233, len 000004)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.0.42:10316 (type 101, seq 010086, ts 93763233, len 000004, mark 0, event 0000000a, end 0, duration 00480)
[2017-06-01 17:18:13] DEBUG[19583][C-00000005] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4)
[2017-06-01 17:18:13] VERBOSE[19586][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:19190 (type 09, seq 001956, ts 015608, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.42:10316 (type 00, seq 030365, ts 015592, len 000160)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:16000 (type 09, seq 033735, ts 014424, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.42:10316 (type 101, seq 010087, ts 93763233, len 000004)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.0.42:10316 (type 101, seq 010087, ts 93763233, len 000004, mark 0, event 0000000a, end 0, duration 00640)
[2017-06-01 17:18:13] DEBUG[19583][C-00000005] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.41:16000 (type 09, seq 021256, ts 016960, len 000160)
[2017-06-01 17:18:13] VERBOSE[19586][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:19190 (type 09, seq 001957, ts 015768, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.42:10316 (type 00, seq 030366, ts 015752, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.42:10316 (type 101, seq 010088, ts 93763233, len 000004)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.0.42:10316 (type 101, seq 010088, ts 93763233, len 000004, mark 0, event 0000000a, end 1, duration 00720)
[2017-06-01 17:18:13] DEBUG[19583][C-00000005] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4)
[2017-06-01 17:18:13] DTMF[19583][C-00000005] channel.c: DTMF end ‘’ received on SIP/9111-00000007, duration 90 ms
[2017-06-01 17:18:13] DTMF[19583][C-00000005] channel.c: DTMF end accepted with begin '’ on SIP/9111-00000007
[2017-06-01 17:18:13] DTMF[19583][C-00000005] channel.c: DTMF end passthrough ‘*’ on SIP/9111-00000007
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:16000 (type 09, seq 033736, ts 014584, len 000160)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.41:16000 (type 09, seq 021257, ts 017120, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.42:10316 (type 101, seq 010089, ts 93763233, len 000004)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.0.42:10316 (type 101, seq 010089, ts 93763233, len 000004, mark 0, event 0000000a, end 1, duration 00720)
[2017-06-01 17:18:13] DEBUG[19583][C-00000005] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4)
[2017-06-01 17:18:13] VERBOSE[19586][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:19190 (type 09, seq 001958, ts 015928, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.42:10316 (type 00, seq 030367, ts 015912, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.42:10316 (type 101, seq 010090, ts 93763233, len 000004)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP RFC2833 from 192.168.0.42:10316 (type 101, seq 010090, ts 93763233, len 000004, mark 0, event 0000000a, end 1, duration 00720)
[2017-06-01 17:18:13] DEBUG[19583][C-00000005] res_rtp_asterisk.c: - RTP 2833 Event: 0000000a (len = 4)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:16000 (type 09, seq 033737, ts 014744, len 000160)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.41:16000 (type 09, seq 021258, ts 017280, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.42:10316 (type 00, seq 010091, ts 93764113, len 000160)
[2017-06-01 17:18:13] VERBOSE[19586][C-00000005] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.41:19190 (type 09, seq 015793, ts 017096, len 000160)
[2017-06-01 17:18:13] VERBOSE[19586][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.41:19190 (type 09, seq 001959, ts 016088, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.42:10316 (type 00, seq 030368, ts 016072, len 000160)
[2017-06-01 17:18:13] VERBOSE[19584][C-00000006] res_rtp_asterisk.c: Sent RTP packet to 192.168.0.41:16000 (type 09, seq 021259, ts 017440, len 000160)
[2017-06-01 17:18:13] VERBOSE[19583][C-00000005] res_rtp_asterisk.c: Got RTP packet from 192.168.0.42:10316 (type 00, seq 010092, ts 93764273, len 000160)
How does that match up in regards to your application?
If you mean the timing relation, the log lines appear immediately when I press the star key, while the event to my app is received a second later.
There should be no delay for the star DTMF key, if you can reproduce it with a simple application I’d suggest filing an issue[1] with details.
I noticed that the console log actually shows the problem. In the log bellow, you can see that on 16:22:33 Asterisk detected the star digit.However, on 16:22:37 it shows again the reception of the start digit, and this is the event which appears on the ARI application. The digit was pressed once, of course. Do you have any idea what is the difference between these two events?
[2017-06-02 16:22:33] DTMF[25561][C-00000012] channel.c: DTMF begin ‘’ received on SIP/9111-0000001a
[2017-06-02 16:22:33] DTMF[25561][C-00000012] channel.c: DTMF begin passthrough '’ on SIP/9111-0000001a
[2017-06-02 16:22:33] DTMF[25561][C-00000012] channel.c: DTMF end ‘’ received on SIP/9111-0000001a, duration 200 ms
[2017-06-02 16:22:33] DTMF[25561][C-00000012] channel.c: DTMF end accepted with begin '’ on SIP/9111-0000001a
[2017-06-02 16:22:33] DTMF[25561][C-00000012] channel.c: DTMF end passthrough ‘’ on SIP/9111-0000001a
[2017-06-02 16:22:36] VERBOSE[25563][C-00000013] file.c: <SIP/MainSystemTrunk-0000001c> Playing ‘…/…/…/…/home/asterisk/ToraPrompts/Hebrew/ulaw/Special1.ulaw’ (language ‘en’)
[2017-06-02 16:22:37] DTMF[25563][C-00000013] channel.c: DTMF begin '’ received on SIP/MainSystemTrunk-0000001c
[2017-06-02 16:22:37] DTMF[25563][C-00000013] channel.c: DTMF begin ignored ‘’ on SIP/MainSystemTrunk-0000001c
[2017-06-02 16:22:37] DTMF[25563][C-00000013] channel.c: DTMF end '’ received on SIP/MainSystemTrunk-0000001c, duration 160 ms
[2017-06-02 16:22:37] DTMF[25563][C-00000013] channel.c: DTMF end passthrough ‘*’ on SIP/MainSystemTrunk-0000001c
Sorry, I figured out the double events. The first is the calling station pressure of the key. The second is its reception. Anyway, you can see a long delay between them.
I don’t understand what you mean by that. Are you saying that the DTMF from MainSystemTrunk is delayed? If so, then it doesn’t appear to be as a result of the Asterisk which these logs themselves came from. Those messages are output as RTP is received, if they are delayed - then the RTP from MainSystemTrunk did not contain the DTMF digit until that time.
I think these last logs are misleading since I used an extension connected to the asterisk server for calling the application. In this case there really should be a delay.
I’m very confused now at what you’ve presented. Which is with a SIP device directly connected and calling the app?
I’m sorry I made it confusing. I’ll prepare tomorrow new set of logs clearly showing each scenario.
O.K. made a better test. Undoubtedly, when calling from a device that is not connected to the Asterisk server, the log file shows the dtmf detection in a one second delay. I turned RTP debug on and dtmf detection for console, and the events appear on the console about 1 second after I press the digits. Pressing any other digit shows the event on the console immediately.
Thanks,
Eyal.
That would mean that it is the other side and not Asterisk itself. It’s up to the other side to provide the digit out of band via RTP and Asterisk acts on that. Asterisk doesn’t do any audio analysis in that case.
I see your logic, but I tried with two different carriers with the same results.
That doesn’t change the result of what you are seeing. If the RTP does not contain the digit until a second later there’s nothing Asterisk can do about that.
O.K.’ I’ll have a check with our carrier and update you afterwards.
Thanks.
After some tests, it seems to be a problem caused by the fact that this (backup) server is not connected directly to the trunk but the calls are routed to it through another asterisk server. On the other server that is directly connected there is no delay. Although strange, it does not affect our production server.
Thanks for the support helping to understand the problem.