IVR disconnecting incoming calls

FreePBX
1

Since updating to IVR module version 14.0.3 we have noted that more often than not calls on the DDI which routes to our IVR menu are being terminated without the initial announcement being played. Occasionally (very occasionally) a call will get through to the IVR and be able to interact with it the normal way.

As a temporary fix, I’ve diverted the inbound route to the queue that is called by this IVR on timeout, this is not ideal, as the option to allow staff to speed-dial in to a staff menu is no longer there.

In case there was corruption in the IVR setting, I’ve tried creating a second IVR with the same settings, and it also disconnects calls.

Any pointers as to where to look in order to debug this would be appreciated.

Versions:

Asterisk: 13.22.0

FreePBX: 12.7.5-1807-1.sng7 / 14.0.3.19

IVR: 14.0.3

Log extract (anonymized):

[2018-10-02 22:24:01] VERBOSE[12342][C-00000003] netsock2.c: Using SIP RTP TOS bits 184
[2018-10-02 22:24:01] VERBOSE[12342][C-00000003] netsock2.c: Using SIP RTP CoS mark 5
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:1] Set("SIP/Orbtalk-Trunk-00000004", "__DIRECTION=INBOUND") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:2] Gosub("SIP/Orbtalk-Trunk-00000004", "sub-record-check,s,1(in,441231231231,yes)") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/Orbtalk-Trunk-00000004", "0?initialized") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:2] Set("SIP/Orbtalk-Trunk-00000004", "__REC_STATUS=INITIALIZED") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:3] Set("SIP/Orbtalk-Trunk-00000004", "NOW=1538519041") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:4] Set("SIP/Orbtalk-Trunk-00000004", "__DAY=02") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:5] Set("SIP/Orbtalk-Trunk-00000004", "__MONTH=10") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:6] Set("SIP/Orbtalk-Trunk-00000004", "__YEAR=2018") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:7] Set("SIP/Orbtalk-Trunk-00000004", "__TIMESTR=20181002-222401") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:8] Set("SIP/Orbtalk-Trunk-00000004", "__FROMEXTEN=unknown") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:9] Set("SIP/Orbtalk-Trunk-00000004", "__MON_FMT=wav") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/Orbtalk-Trunk-00000004", "Recordings initialized") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/Orbtalk-Trunk-00000004", "0?Set(ARG3=dontcare)") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:12] Set("SIP/Orbtalk-Trunk-00000004", "REC_POLICY_MODE_SAVE=") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/Orbtalk-Trunk-00000004", "0?Set(REC_STATUS=NO)") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/Orbtalk-Trunk-00000004", "2?checkaction") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/Orbtalk-Trunk-00000004", "1?sub-record-check,in,1") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx_builtins.c: Goto (sub-record-check,in,1)
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/Orbtalk-Trunk-00000004", "Inbound Recording Check to 441231231231") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [in@sub-record-check:2] Set("SIP/Orbtalk-Trunk-00000004", "FROMEXTEN=unknown") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/Orbtalk-Trunk-00000004", "12?Set(FROMEXTEN=447762123456)") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/Orbtalk-Trunk-00000004", "recordcheck,1(yes,in,441231231231)") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/Orbtalk-Trunk-00000004", "Starting recording check against yes") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/Orbtalk-Trunk-00000004", "yes") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx_builtins.c: Goto (sub-record-check,recordcheck,9)
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:9] ExecIf("SIP/Orbtalk-Trunk-00000004", "0?Return()") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:10] Set("SIP/Orbtalk-Trunk-00000004", "__REC_POLICY_MODE=YES") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:11] Goto("SIP/Orbtalk-Trunk-00000004", "startrec") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx_builtins.c: Goto (sub-record-check,recordcheck,16)
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp("SIP/Orbtalk-Trunk-00000004", "Starting recording: in, 441231231231") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:17] Set("SIP/Orbtalk-Trunk-00000004", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack
[2018-10-02 22:24:01] ERROR[16277][C-00000003] pbx_functions.c: Function AUDIOHOOK_INHERIT not registered
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:18] Set("SIP/Orbtalk-Trunk-00000004", "__CALLFILENAME=in-441231231231-447762123456-20181002-222401-1538519041.10") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:19] MixMonitor("SIP/Orbtalk-Trunk-00000004", "2018/10/02/in-441231231231-447762123456-20181002-222401-1538519041.10.wav,abi(LOCAL_MIXMON_ID),/var/lib/asterisk/bin/emailrecording.sh ^{TIMESTR} ^{FROMEXTEN} ^{CALLFILENAME} ^{UNIQUEID} ^{ARG3}") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:20] Set("SIP/Orbtalk-Trunk-00000004", "__MIXMON_ID=0x7f95a4041f50") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:21] Set("SIP/Orbtalk-Trunk-00000004", "__RECORD_ID=SIP/Orbtalk-Trunk-00000004") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:22] Set("SIP/Orbtalk-Trunk-00000004", "__REC_STATUS=RECORDING") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:23] Set("SIP/Orbtalk-Trunk-00000004", "CDR(recordingfile)=in-441231231231-447762123456-20181002-222401-1538519041.10.wav") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [recordcheck@sub-record-check:24] Return("SIP/Orbtalk-Trunk-00000004", "") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [in@sub-record-check:5] Return("SIP/Orbtalk-Trunk-00000004", "") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:3] Set("SIP/Orbtalk-Trunk-00000004", "CHANNEL(tonezone)=uk") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:4] Set("SIP/Orbtalk-Trunk-00000004", "__FROM_DID=441231231231") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:5] Set("SIP/Orbtalk-Trunk-00000004", "returnhere=1") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:6] Gosub("SIP/Orbtalk-Trunk-00000004", "app-blacklist-check,s,1()") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/Orbtalk-Trunk-00000004", "0?blacklisted") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/Orbtalk-Trunk-00000004", "CALLED_BLACKLIST=1") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/Orbtalk-Trunk-00000004", "") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:7] Set("SIP/Orbtalk-Trunk-00000004", "CDR(did)=441231231231") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:8] GotoIf("SIP/Orbtalk-Trunk-00000004", "0?") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:9] ExecIf("SIP/Orbtalk-Trunk-00000004", "0 ?Set(CALLERID(name)=447762123456)") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:10] Set("SIP/Orbtalk-Trunk-00000004", "__MOHCLASS=") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:11] Set("SIP/Orbtalk-Trunk-00000004", "__REVERSAL_REJECT=FALSE") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:12] GotoIf("SIP/Orbtalk-Trunk-00000004", "1?post-reverse-charge") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx_builtins.c: Goto (from-trunk,441231231231,14)
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:14] NoOp("SIP/Orbtalk-Trunk-00000004", "") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:15] Set("SIP/Orbtalk-Trunk-00000004", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:16] Set("SIP/Orbtalk-Trunk-00000004", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:17] Set("SIP/Orbtalk-Trunk-00000004", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:18] Set("SIP/Orbtalk-Trunk-00000004", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:19] NoOp("SIP/Orbtalk-Trunk-00000004", "CallerID Entry Point") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [441231231231@from-trunk:20] Goto("SIP/Orbtalk-Trunk-00000004", "ivr-1,s,1") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx_builtins.c: Goto (ivr-1,s,1)
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@ivr-1:1] Set("SIP/Orbtalk-Trunk-00000004", "_IVR_CONTEXT_ivr-1=") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@ivr-1:2] Set("SIP/Orbtalk-Trunk-00000004", "_IVR_CONTEXT=ivr-1") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@ivr-1:3] Set("SIP/Orbtalk-Trunk-00000004", "__IVR_RETVM=") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@ivr-1:4] Set("SIP/Orbtalk-Trunk-00000004", "__RVOL=14") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@ivr-1:5] GotoIf("SIP/Orbtalk-Trunk-00000004", "0?skip") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@ivr-1:6] Answer("SIP/Orbtalk-Trunk-00000004", "") in new stack
[2018-10-02 22:24:01] VERBOSE[16278][C-00000003] app_mixmonitor.c: Begin MixMonitor Recording SIP/Orbtalk-Trunk-00000004
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Spawn extension (ivr-1, s, 6) exited non-zero on 'SIP/Orbtalk-Trunk-00000004'
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [h@ivr-1:1] Hangup("SIP/Orbtalk-Trunk-00000004", "") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Spawn extension (ivr-1, h, 1) exited non-zero on 'SIP/Orbtalk-Trunk-00000004'
[2018-10-02 22:24:01] VERBOSE[16278][C-00000003] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2018-10-02 22:24:01] VERBOSE[16278][C-00000003] app_mixmonitor.c: Executing [/var/lib/asterisk/bin/emailrecording.sh 20181002-222401 447762123456 in-441231231231-447762123456-20181002-222401-1538519041.10 1538519041.10 441231231231]
[2018-10-02 22:24:06] VERBOSE[16278][C-00000003] app_mixmonitor.c: End MixMonitor Recording SIP/Orbtalk-Trunk-00000004
2

I don’t see any issues on a system with the same asterisk and IVR version you have.

[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [s@ivr-1:6] Answer("SIP/Orbtalk-Trunk-00000004", "") in new stack
[2018-10-02 22:24:01] VERBOSE[16278][C-00000003] app_mixmonitor.c: Begin MixMonitor Recording SIP/Orbtalk-Trunk-00000004
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Spawn extension (ivr-1, s, 6) exited non-zero on 'SIP/Orbtalk-Trunk-00000004'
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Executing [h@ivr-1:1] Hangup("SIP/Orbtalk-Trunk-00000004", "") in new stack
[2018-10-02 22:24:01] VERBOSE[16277][C-00000003] pbx.c: Spawn extension (ivr-1, h, 1) exited non-zero on 'SIP/Orbtalk-Trunk-00000004'

I am no expert, but it seems to me like the IVR has trouble answering.

Two suggestions:
1 Try to set Answer > Yes on the inbound route.
2 Try to re-create the IVR.

1 Like
3

Cheers. I don’t know what happened, but after sleep I forced the module manager to reinstall IVR and it’s been working again for the most part… However… something slightly hinkey happened in that out of 10 calls which were answered immediately by the IVR, one went to indefinite ringing.

My follow-up question… Is it possible that there is duplicate data for the inbound route, and on some random occasions it’s loading incorrect routing information? If so, is there a way to force-refresh and clean all the conf files? I wouldn’t even know where to start looking for such an anomoly, and didn’t think to log the time which it happened to go back and trace the log :persevere:

4

It’s a database table, you mean to ask if it’s possible that the table is corrupted? could be.

Easiest way to figure out whats wrong would be a call trace. Just keep in mind to document timings next time it happens.

5

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.