Sudden issues with IVR

I have been made aware that after an incoming call goes to a ringgroup, and then an overflow ringgroup, it is failing to go to the IVR we have setup.

Instead of playing the IVR, I get a busy signal.

This previously worked and I haven’t made any changes to our server.

I am not seeing anything in the log files, I even see where it goes to set the IVR audio file to play.

Not sure what to do or how to troubleshoot this. Any help would be appreciated!

have you done a packet capture to see the flow of the call? Might provide some insight as to where the busy is coming from.

As in a tcpdump and then analyze in wireshark?

Yep yep

Ok - I am capturing it right now. Although, last time I tried to do this Wireshark didn’t make a bunch of sense to me. (as in, what to look for). Will update soon

if you can post the capture people can take a look at it. Or do a screen snip of the entire call flow. (Telephony>Voip Calls>Highlight the legs of your call and hit Flow)

It was configured to go to ring group A. If no answer, ring group B. If no answer on B, go to IVR.

This is not working.

I switched it to go to ring group A, and if no answer go to IVR, and it works.

Does this tell anyone anything?

Also, I have done the packet capture… but I cannot share the file (sensitive info), and I am so confused looking at this I don’t know what to give you.

This maybe a long shot but try disabling Send Progress under the ring group settings.

ok, no worries. How long do you have it ringing, Ring Time, on Ring Group A before going to Ring Group B, and Ring Group B before going to the IVR? May be able to do a little test on this to get an idea.

Or try @necits2015 suggestion.

It sounds to me like possibly a time out issue where it acts like a “No Answer/Busy Here” make sense?

15 on both.

Trying to disable Send Progress now.

Send Progress disabling didn’t work.

I don’t know if this makes a difference, but between the two ring groups there are 5 actual extensions.

Ring group A dials extensions 1,2,3 ringall for 15seconds

Ring group B dials extensions 1,2,3,4,5 ringall for 15seconds -> IVR.

I am going to have it go to Ring Group B first and then straight to IVR to see if that works like ring group a->IVR

Ok, so

Inbound call -> Ring Group A - > IVR works
Inbound call -> Ring Group B - > IVR works
Inbound call - > Ring Group A (no answer) -> Ring Group B (no answer) -> IVR doesn’t work.

Also, in the third scenario, ring group B doesn’t ring a full 15 seconds. It rings a couple times, maybe 3 times and then goes to busy signal.

It feels like it is timing out.

OK if disabling send progress did nothing I would re-enable it. What version of asterisk/freepbx? Chan_Sip or pjsip? Can you provide log info while this is happening? (/var/log/asterisk/full)?

Well a quick test you could do is change your ring time to 10 seconds or so for both ring groups, See if that makes a difference.

Was thinking the same thing :slight_smile:

Freepbx core is version 13.0.117
Asterisk is returning 13.5

Chan_SIP

I will try to find the appropriate logs. It is hard because of how many phones we have going at any given time.

I will also try the ‘10’ seconds

OK - Output:

[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Caller ID name is 'IDPR: WIRELESS CALLER' number is '719xxx00x8'
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Methodology of ring is 'ringall'
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Added extension 401 to extension map
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Added extension 403 to extension map
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Added extension 304 to extension map
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Added extension 305 to extension map
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 401 cf is disabled
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 403 cf is disabled
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 304 cf is disabled
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 305 cf is disabled
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 401 do not disturb is disabled
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 403 do not disturb is disabled
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 304 do not disturb is disabled
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 305 do not disturb is disabled
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: EXTENSION_STATE: 0 (NOT_INUSE)
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 401 has ExtensionState: 0
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Checking CW and CFB status for extension 401
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: dbset CALLTRACE/401 to 719xxx0098
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: dbset CALLTRACE/403 to 719xxx0098
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: EXTENSION_STATE: 1 (INUSE)
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 304 has ExtensionState: 1
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Checking CW and CFB status for extension 304
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 304 is not available to be called
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 304 has call waiting disabled
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: EXTENSION_STATE: 1 (INUSE)
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 305 has ExtensionState: 1
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Checking CW and CFB status for extension 305
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 305 is not available to be called
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Extension 305 has call waiting disabled
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: dialparties.agi: Filtered ARG3: 401-403
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] res_agi.c: <SIP/cbeyond-in-0000b5b5>AGI Script dialparties.agi completed, returning 0
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:9] NoOp("SIP/cbeyond-in-0000b5b5", "Returned from dialparties with groups to dial") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:10] Set("SIP/cbeyond-in-0000b5b5", "LOOPCNT=2") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:11] Set("SIP/cbeyond-in-0000b5b5", "ITER=1") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:12] Set("SIP/cbeyond-in-0000b5b5", "EXTTOCALL=401") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:13] NoOp("SIP/cbeyond-in-0000b5b5", "Working with 401") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:14] ExecIf("SIP/cbeyond-in-0000b5b5", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:15] ExecIf("SIP/cbeyond-in-0000b5b5", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:16] Set("SIP/cbeyond-in-0000b5b5", "ITER=2") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:17] GotoIf("SIP/cbeyond-in-0000b5b5", "1?ndloopbegin") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Goto (macro-dial,s,12)
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:12] Set("SIP/cbeyond-in-0000b5b5", "EXTTOCALL=403") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:13] NoOp("SIP/cbeyond-in-0000b5b5", "Working with 403") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:14] ExecIf("SIP/cbeyond-in-0000b5b5", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:15] ExecIf("SIP/cbeyond-in-0000b5b5", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:16] Set("SIP/cbeyond-in-0000b5b5", "ITER=3") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:17] GotoIf("SIP/cbeyond-in-0000b5b5", "0?ndloopbegin") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:18] Macro("SIP/cbeyond-in-0000b5b5", "dial-ringall-predial-hook,") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:1] MacroExit("SIP/cbeyond-in-0000b5b5", "") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:19] Dial("SIP/cbeyond-in-0000b5b5", "SIP/401&SIP/403,10,trM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] netsock2.c: Using SIP RTP TOS bits 184
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] netsock2.c: Using SIP RTP CoS mark 5
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] netsock2.c: Using SIP RTP TOS bits 184
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] netsock2.c: Using SIP RTP CoS mark 5
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_stack.c: SIP/401-0000b5b8 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:1] NoOp("SIP/401-0000b5b8", "Applying SIP Headers to channel") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:2] Set("SIP/401-0000b5b8", "SIPHEADERKEYS=") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:3] While("SIP/401-0000b5b8", "0") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_while.c: Jumping to priority 7
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:8] Return("SIP/401-0000b5b8", "") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_stack.c: Spawn extension (from-internal, 308, 1) exited non-zero on 'SIP/401-0000b5b8'
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_stack.c: SIP/401-0000b5b8 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_stack.c: SIP/403-0000b5b9 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:1] NoOp("SIP/403-0000b5b9", "Applying SIP Headers to channel") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:2] Set("SIP/403-0000b5b9", "SIPHEADERKEYS=") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:3] While("SIP/403-0000b5b9", "0") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_while.c: Jumping to priority 7
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:8] Return("SIP/403-0000b5b9", "") in new stack
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_stack.c: Spawn extension (from-internal, 308, 1) exited non-zero on 'SIP/403-0000b5b9'
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_stack.c: SIP/403-0000b5b9 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-01-05 14:05:14] VERBOSE[16975] chan_sip.c: Extension Changed 401[ext-local] new state Ringing for Notify User 404
[2017-01-05 14:05:14] VERBOSE[16975] chan_sip.c: Extension Changed 401[ext-local] new state Ringing for Notify User 402
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_dial.c: Called SIP/401
[2017-01-05 14:05:14] VERBOSE[16975] chan_sip.c: Extension Changed 401[ext-local] new state Ringing for Notify User 304
[2017-01-05 14:05:14] VERBOSE[16975] chan_sip.c: Extension Changed 401[ext-local] new state Ringing for Notify User 303
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_dial.c: Called SIP/403
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_dial.c: SIP/403-0000b5b9 connected line has changed. Saving it until answer for SIP/cbeyond-in-0000b5b5
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_dial.c: SIP/401-0000b5b8 connected line has changed. Saving it until answer for SIP/cbeyond-in-0000b5b5
[2017-01-05 14:05:14] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Ringing for Notify User 301
[2017-01-05 14:05:14] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Ringing for Notify User 404
[2017-01-05 14:05:14] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Ringing for Notify User 304
[2017-01-05 14:05:14] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Ringing for Notify User 306
[2017-01-05 14:05:14] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Ringing for Notify User 401
[2017-01-05 14:05:14] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Ringing for Notify User 303
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_dial.c: SIP/403-0000b5b9 is ringing
[2017-01-05 14:05:14] VERBOSE[19863][C-00004813] app_dial.c: SIP/401-0000b5b8 is ringing
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] app_dial.c: Nobody picked up in 10000 ms
[2017-01-05 14:05:24] VERBOSE[16975] chan_sip.c: Extension Changed 401[ext-local] new state Idle for Notify User 404
[2017-01-05 14:05:24] VERBOSE[16975] chan_sip.c: Extension Changed 401[ext-local] new state Idle for Notify User 402
[2017-01-05 14:05:24] VERBOSE[16975] chan_sip.c: Extension Changed 401[ext-local] new state Idle for Notify User 304
[2017-01-05 14:05:24] VERBOSE[16975] chan_sip.c: Extension Changed 401[ext-local] new state Idle for Notify User 303
[2017-01-05 14:05:24] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Idle for Notify User 301
[2017-01-05 14:05:24] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Idle for Notify User 404
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:20] Set("SIP/cbeyond-in-0000b5b5", "DIALSTATUS=NOANSWER") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:21] GosubIf("SIP/cbeyond-in-0000b5b5", "0?NOANSWER,1()") in new stack
[2017-01-05 14:05:24] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Idle for Notify User 304
[2017-01-05 14:05:24] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Idle for Notify User 306
[2017-01-05 14:05:24] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Idle for Notify User 401
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:22] NoOp("SIP/cbeyond-in-0000b5b5", "Returning since nobody answered") in new stack
[2017-01-05 14:05:24] VERBOSE[16975] chan_sip.c: Extension Changed 403[ext-local] new state Idle for Notify User 303
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:23] MacroExit("SIP/cbeyond-in-0000b5b5", "") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:15] Gosub("SIP/cbeyond-in-0000b5b5", "sub-record-cancel,s,1()") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:1] Return("SIP/cbeyond-in-0000b5b5", "") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:16] Set("SIP/cbeyond-in-0000b5b5", "RingGroupMethod=") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:17] GotoIf("SIP/cbeyond-in-0000b5b5", "0?nodest") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:18] Set("SIP/cbeyond-in-0000b5b5", "__NODEST=") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:19] Macro("SIP/cbeyond-in-0000b5b5", "blkvm-clr,") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:1] Set("SIP/cbeyond-in-0000b5b5", "SHARED(BLKVM,SIP/cbeyond-in-0000b5b5)=") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:2] Set("SIP/cbeyond-in-0000b5b5", "GOSUB_RETVAL=") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:3] MacroExit("SIP/cbeyond-in-0000b5b5", "") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:20] Goto("SIP/cbeyond-in-0000b5b5", "ivr-1,s,1") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Goto (ivr-1,s,1)
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:1] Set("SIP/cbeyond-in-0000b5b5", "TIMEOUT_LOOPCOUNT=0") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:2] Set("SIP/cbeyond-in-0000b5b5", "INVALID_LOOPCOUNT=0") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:3] Set("SIP/cbeyond-in-0000b5b5", "_IVR_CONTEXT_ivr-1=") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:4] Set("SIP/cbeyond-in-0000b5b5", "_IVR_CONTEXT=ivr-1") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:5] Set("SIP/cbeyond-in-0000b5b5", "__IVR_RETVM=") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:6] GotoIf("SIP/cbeyond-in-0000b5b5", "0?skip") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:7] Answer("SIP/cbeyond-in-0000b5b5", "") in new stack
[2017-01-05 14:05:24] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:8] Wait("SIP/cbeyond-in-0000b5b5", "1") in new stack
[2017-01-05 14:05:25] VERBOSE[19863][C-00004813] pbx.c: Spawn extension (ivr-1, s, 8) exited non-zero on 'SIP/cbeyond-in-0000b5b5'
[2017-01-05 14:05:25] VERBOSE[19863][C-00004813] pbx.c: Executing [[email protected]:1] Hangup("SIP/cbeyond-in-0000b5b5", "") in new stack

The End of that output is where it finally trys to go to IVR.

Did you try changing to ring times?

I did - that didn’t fix it.