Agent Answers Call, Queue Ignores it

PitzKey · May 20, 2024, 1:23pm

Hello,

FreePBX 16
Asterisk 18.20.0

Call trace: [2024-05-16 15:45:51] VERBOSE[57540][C-00021d19] pbx.c: Executing [8004448888@fr - Pastebin.com

Call logic:

Caller calls in, enters extension 106 which forwards the call to queue 8002.
8002 has an agent ringtime of 8 seconds, wrapuptime of 8 seconds and the ring strategy is rrmemory.
We are using the U option to call a custom context so we can pass the agent information (answered) to an external application, as well as an hangup handler (hangup details)

The call rang by extension 329 (pastebin line 608)

[2024-05-16 15:46:06] VERBOSE[58083][C-00021d19] app_dial.c: Called PJSIP/329/sip:[email protected]:5060
[2024-05-16 15:46:06] VERBOSE[57540][C-00021d19] app_queue.c: Local/329@from-queue-0010f30f;1 is ringing
[2024-05-16 15:46:06] VERBOSE[58083][C-00021d19] app_dial.c: Connected line update to Local/329@from-queue-0010f30f;2 prevented.
[2024-05-16 15:46:06] VERBOSE[58083][C-00021d19] app_dial.c: PJSIP/329-000595c3 is ringing
[2024-05-16 15:46:06] VERBOSE[57540][C-00021d19] app_queue.c: Local/329@from-queue-0010f30f;1 is ringing

They answered the call on the 8th second (pastebin line 613)

[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_dial.c: PJSIP/329-000595c3 answered Local/329@from-queue-0010f30f;2
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-auto-blkvm:1] ExecIf("PJSIP/329-000595c3", "1?Set(CDR(recordingfile)=in-8004448888-2120001111-20240516-154551-1715888751.2659624.wav)") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-auto-blkvm:2] Set("PJSIP/329-000595c3", "__MACRO_RESULT=") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-auto-blkvm:3] Set("PJSIP/329-000595c3", "CFIGNORE=") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-auto-blkvm:4] Set("PJSIP/329-000595c3", "MASTER_CHANNEL(CFIGNORE)=") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-auto-blkvm:5] Set("PJSIP/329-000595c3", "FORWARD_CONTEXT=from-internal") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-auto-blkvm:6] Set("PJSIP/329-000595c3", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-auto-blkvm:7] Macro("PJSIP/329-000595c3", "blkvm-clr,") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-blkvm-clr:1] Set("PJSIP/329-000595c3", "SHARED(BLKVM,PJSIP/Upstream1-000595bb)=") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-blkvm-clr:2] Set("PJSIP/329-000595c3", "GOSUB_RETVAL=") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("PJSIP/329-000595c3", "") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-auto-blkvm:8] ExecIf("PJSIP/329-000595c3", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=329/sip:[email protected]:5060)") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-auto-blkvm:9] ExecIf("PJSIP/329-000595c3", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=)") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_stack.c: PJSIP/329-000595c3 Internal Gosub(post-incomingCall,s,1(s,1)) start
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-incomingCall:1] NoOp("PJSIP/329-000595c3", "INBOUND - Send Post") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-incomingCall:2] ExecIf("PJSIP/329-000595c3", "0?Goto(call-volume-pickup,s,1)") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-incomingCall:3] GotoIf("PJSIP/329-000595c3", "1?setVar:continue") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx_builtins.c: Goto (post-incomingCall,s,4)
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-incomingCall:4] Set("PJSIP/329-000595c3", "CallerID=ABC Company") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-incomingCall:5] GotoIf("PJSIP/329-000595c3", "0?setVar2:post") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx_builtins.c: Goto (post-incomingCall,s,7)
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-incomingCall:7] AGI("PJSIP/329-000595c3", "post_inbound.sh,ABC Company,2120001111,329,1715888766.2659656,Answered") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/post_inbound.sh

But the queue decided to ignore the call and continue (line 636)

[2024-05-16 15:46:14] VERBOSE[57540][C-00021d19] app_queue.c: Nobody picked up in 8000 ms
[2024-05-16 15:46:14] VERBOSE[57540][C-00021d19] app_queue.c:     -- LazyMembers debugging - Numbusies: 0, Nummems: 6
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] res_agi.c: <PJSIP/329-000595c3>AGI Script post_inbound.sh completed, returning 0
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-incomingCall:8] Set("PJSIP/329-000595c3", "CHANNEL(hangup_handler_push)=post-hangup-inbound,s,1") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-incomingCall:9] NoOp("PJSIP/329-000595c3", "Continue call") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-incomingCall:10] Return("PJSIP/329-000595c3", "") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_stack.c: Spawn extension (macro-dial-one, s, 1) exited non-zero on 'PJSIP/329-000595c3'
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_stack.c: PJSIP/329-000595c3 Internal Gosub(post-incomingCall,s,1(s,1)) complete GOSUB_RETVAL=
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_stack.c: PJSIP/329-000595c3 Internal Gosub(post-hangup-inbound,s,1) start
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-hangup-inbound:1] Set("PJSIP/329-000595c3", "CallerID=ABC Company") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-hangup-inbound:2] GotoIf("PJSIP/329-000595c3", "0?setVar2:post") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx_builtins.c: Goto (post-hangup-inbound,s,4)
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-hangup-inbound:4] AGI("PJSIP/329-000595c3", "post_inbound.sh,ABC Company,2120001111,329,1715888766.2659656,CallEnded") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/post_inbound.sh
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] res_agi.c: <PJSIP/329-000595c3>AGI Script post_inbound.sh completed, returning 0
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@post-hangup-inbound:5] Return("PJSIP/329-000595c3", "") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_stack.c: Spawn extension (macro-dial-one, s, 1) exited non-zero on 'PJSIP/329-000595c3'
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_stack.c: PJSIP/329-000595c3 Internal Gosub(post-hangup-inbound,s,1) complete GOSUB_RETVAL=
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_stack.c: PJSIP/329-000595c3 Internal Gosub(crm-hangup,s,1) start
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/329-000595c3", "Sending Hangup to CRM") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/329-000595c3", "HANGUP CAUSE: 16") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/329-000595c3", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/329-000595c3", "MASTER CHANNEL: 1715888766.2659656 = 1715888751.2659624") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/329-000595c3", "1?return") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx_builtins.c: Goto (crm-hangup,s,8)
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/329-000595c3", "") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_stack.c: Spawn extension (macro-dial-one, s, 1) exited non-zero on 'PJSIP/329-000595c3'
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_stack.c: PJSIP/329-000595c3 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_macro.c: Spawn extension (macro-dial-one, s, 56) exited non-zero on 'Local/329@from-queue-0010f30f;2' in macro 'dial-one'
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Spawn extension (from-queue-exten-internal, 329, 9) exited non-zero on 'Local/329@from-queue-0010f30f;2'
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [h@from-queue-exten-internal:1] Macro("Local/329@from-queue-0010f30f;2", "hangupcall,") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("Local/329@from-queue-0010f30f;2", "1?theend") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("Local/329@from-queue-0010f30f;2", "0?Set(CDR(recordingfile)=)") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Executing [s@macro-hangupcall:4] Hangup("Local/329@from-queue-0010f30f;2", "") in new stack
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'Local/329@from-queue-0010f30f;2' in macro 'hangupcall'
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Spawn extension (from-queue-exten-internal, h, 1) exited non-zero on 'Local/329@from-queue-0010f30f;2'

And went to the next agent (line 673)

[2024-05-16 15:46:15] VERBOSE[57540][C-00021d19] app_queue.c: Called Local/335@from-queue/n

So… What am I missing? I thought that if the local channel is answered then the Queue Application would consider this an Answer. If so, why did it ignore the answer and move to the next agent?

Thanks

BlazeStudios · May 20, 2024, 3:02pm

We probably will need to see a SIP trace from PJSIP logger to see what is going on.

So you got two things here, Queue ↔ Local Channel L1 (leg 1) and Local Channel L2 (leg 2) ↔ PJSIP/329 and since by default, it looks like FreePBX disabled optimization on local channels between the queue and agent, the call goes over the local channel. While you are seeing that PJSIP/239 answered Local Channel L2 you’re going passed what is happening on Local Channel L1.

Remember how Local channels work, when you see this:

[2024-05-16 15:46:06] VERBOSE[57540][C-00021d19] app_queue.c: Local/329@from-queue-0010f30f;1 is ringing
[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_dial.c: PJSIP/329-000595c3 answered Local/329@from-queue-0010f30f;2

The call isn’t being answered at the queue level, it’s the second leg of the local channel that called PJSIP/329. The two legs of the local channel, Local/329@from-queue-0010f30f;2 and Local/329@from-queue-0010f30f;1 still haven’t bridged yet. Local/329@from-queue-0010f30f;1 still thinks it’s ringing.

So you end up with Local/329@from-queue-0010f30f;1 not thinking someone picked up the call in 8 seconds.
[2024-05-16 15:46:14] VERBOSE[57540][C-00021d19] app_queue.c: Nobody picked up in 8000 ms

Then you have these entries:

[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] app_stack.c: Spawn extension (macro-dial-one, s, 1) exited non-zero on 'PJSIP/329-000595c3'

[2024-05-16 15:46:14] VERBOSE[58083][C-00021d19] pbx.c: Spawn extension (from-queue-exten-internal, 329, 9) exited non-zero on 'Local/329@from-queue-0010f30f;2'

Keep in mind, the log file doesn’t log things in order. It’s a race when multiple things hit it at once. So basically the local channel Local/329@from-queue-0010f30f;2 (L2) ends the call to PJSIP/329 because Local/329@from-queue-0010f30f;1 believed it timed out and canceled the call.

david55 · May 20, 2024, 3:45pm

Whilst I think that the implementation of local channels has changed a lot since I looked deep into the internals, if the ;2 side receives AST_CONTROL_ANSWER, that should be output on the ;1 side. app_dial should pass the control message to the incoming channel, regardless of whether it is a local or external one, so the ;2 side should see it.

l think there could be an Asterisk bug here, and, presumably a recent one.

PitzKey · May 20, 2024, 4:26pm

Thanks tom, that was my suspicion… with that being said, I am curious if the FreePBX Macro auto-blkvm and the U option that calls post-incomingCall that gets executed after the answer and before getting bridged contributes to this issue. Although they all get executed within the same second.

Thanks David. This was recently brought to our attention, but I cannot afford to downgrade them to Asterisk16 and test.

I will try to dig deeper.

jcolp · May 20, 2024, 4:44pm

It’s executing a script upon answer. If that script execution results in total calling time exceeding the timeout, I believe the queue would consider the agent channel unanswered. That’s because to the queue the channel hasn’t been answered yet - script is still executing. I think that’s what happened.

BlazeStudios · May 21, 2024, 11:19am

Just a side note here but you’re going to need to update what you’re doing with the Queues and/or dialing extensions for future proofing. There is no more Marco() as of Asterisk v21 meaning you will not be able to do both a Gosub() and a Macro() call from things like Dial() or Queue(), etc.

DIAL_OPTIONS=HhTtrU(post-incomingCall^s^1)M(auto-blkvm) << this is no longer viable in Asterisk 21 and going forward. You will not have the M option for Macro()'s anymore. FreePBX 17 now has calls for auto-blkvm, etc as GoSub calls. So the typical dial string will look more like this from the queue:

DIAL_OPTIONS=HhTtrU(macro-auto-blkvm^s^1) before any modifications are made. You’re basically going to need to make it so your post-incomingCalls calls on the auto-blkvm GoSub within it to make sure both happen.

PitzKey · May 21, 2024, 3:21pm

Interesting. It is a asynchronous bash script and it all executes within the same second.

I am trying to think what other methods can be done, other than listening to AMI and parsing the data.

Looking at the Queue() documentation:

gosub - Will run a gosub on the called party’s channel (the queue member) once the parties are connected. The subroutine execution starts in the named context at the s exten and priority 1.

Does that occur after they are bridged, or we’ll have the same issue here?

Thanks

jcolp · May 21, 2024, 3:25pm

After answer, before bridge, within app_queue, so the timeout would not apply since it is answered from the perspective of app_queue.

BlazeStudios · May 21, 2024, 5:07pm

What’s your Agent Timeout set to? How long do you ring agents?

PitzKey · May 21, 2024, 6:22pm

8 seconds

BlazeStudios · May 21, 2024, 7:16pm

@jcolp may correct me but it sounds like you have a race condition. The call took 8 seconds to be answered. It may have been answered on leg 2 just as leg 1 timed out. Simply, seems like the agent is answering just as the queue is timing out the call. It is probably why the next agent who answers in under 8 seconds doesnt have the issue. Based on the log.

jcolp · May 21, 2024, 7:56pm

I have no correction to give, that is what my perusal of the log indicated.

PitzKey · May 23, 2024, 10:47am

I am afraid that something is wrong with this version of Asterisk that we are using.

See full call trace: Queue 8002 - Pastebin.com

Extension 323 called the queue 8002, it tried calling extension 329 but it was busy, so it went to next extension 440, and it rang for 6 seconds, which then responded busy:

[2024-05-22 14:05:22] VERBOSE[81293][C-000231e3] app_dial.c: Called PJSIP/440/sip:[email protected]:5060
[2024-05-22 14:05:22] VERBOSE[81273][C-000231e3] app_queue.c: Local/440@from-queue-0011802a;1 is ringing
[2024-05-22 14:05:22] VERBOSE[81293][C-000231e3] app_dial.c: PJSIP/440-0005c9f2 is ringing
[2024-05-22 14:05:22] VERBOSE[81273][C-000231e3] app_queue.c: Local/440@from-queue-0011802a;1 is ringing
[2024-05-22 14:05:28] VERBOSE[81293][C-000231e3] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)

The queue marked that 440 didn’t answer after 6 seconds:

[2024-05-22 14:05:28] VERBOSE[81273][C-000231e3] app_queue.c: Nobody picked up in 6000 ms

Next extension 328 was busy, so extension 314 was next in line,

[2024-05-22 14:05:28] VERBOSE[81273][C-000231e3] app_queue.c: Called Local/314@from-queue/n
...
[2024-05-22 14:05:28] VERBOSE[81336][C-000231e3] app_dial.c: Called PJSIP/314/sip:[email protected]:5060
[2024-05-22 14:05:28] VERBOSE[81273][C-000231e3] app_queue.c: Local/314@from-queue-0011802c;1 is ringing
[2024-05-22 14:05:28] VERBOSE[81336][C-000231e3] app_dial.c: PJSIP/314-0005c9f3 is ringing
[2024-05-22 14:05:28] VERBOSE[81273][C-000231e3] app_queue.c: Local/314@from-queue-0011802c;1 is ringing

But, after 2 seconds, it stopped ringing 314 and marked that it rang by 314 for 8 seconds.

[2024-05-22 14:05:30] VERBOSE[81273][C-000231e3] app_queue.c: Nobody picked up in 8000 ms

It looks to me like it combined the ring time time of 440 and 314 to reach 8 seconds…

Perhaps I am missing something?

Thanks

jcolp · May 23, 2024, 11:00am

I believe you would want to set this to yes to have the timeout restart:

; If timeoutrestart is set to yes, then the timeout for an agent to answer is
; reset if a BUSY or CONGESTION is received.  This can be useful if agents
; are able to cancel a call with reject or similar.
;
; timeoutrestart = no

PitzKey · May 23, 2024, 11:16am

Thanks. IDK how I missed this…

PitzKey · June 4, 2024, 12:47pm

So apparently, this race condition is happening while executing the default FreePBX Macro() even before the U option is executed.

[2024-06-03 12:25:58] VERBOSE[12812][C-00025afb] app_dial.c: Called PJSIP/357/sip:[email protected]:5060
[2024-06-03 12:25:58] VERBOSE[11765][C-00025afb] app_queue.c: Local/357@from-queue-00127a57;1 is ringing
[2024-06-03 12:25:58] VERBOSE[12812][C-00025afb] app_dial.c: Connected line update to Local/357@from-queue-00127a57;2 prevented.
[2024-06-03 12:25:58] VERBOSE[12812][C-00025afb] app_dial.c: PJSIP/357-000632d8 is ringing
[2024-06-03 12:25:58] VERBOSE[11765][C-00025afb] app_queue.c: Local/357@from-queue-00127a57;1 is ringing
[2024-06-03 12:26:05] VERBOSE[12812][C-00025afb] app_dial.c: PJSIP/357-000632d8 answered Local/357@from-queue-00127a57;2
[2024-06-03 12:26:05] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-auto-blkvm:1] ExecIf("PJSIP/357-000632d8", "1?Set(CDR(recordingfile)=in-8004448888-2120001111-20240603-122528-1717431928.2906834.wav)") in new stack
[2024-06-03 12:26:05] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-auto-blkvm:2] Set("PJSIP/357-000632d8", "__MACRO_RESULT=") in new stack
[2024-06-03 12:26:05] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-auto-blkvm:3] Set("PJSIP/357-000632d8", "CFIGNORE=") in new stack
[2024-06-03 12:26:05] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-auto-blkvm:4] Set("PJSIP/357-000632d8", "MASTER_CHANNEL(CFIGNORE)=") in new stack
[2024-06-03 12:26:05] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-auto-blkvm:5] Set("PJSIP/357-000632d8", "FORWARD_CONTEXT=from-internal") in new stack
[2024-06-03 12:26:05] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-auto-blkvm:6] Set("PJSIP/357-000632d8", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
[2024-06-03 12:26:05] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-auto-blkvm:7] Macro("PJSIP/357-000632d8", "blkvm-clr,") in new stack
[2024-06-03 12:26:05] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-blkvm-clr:1] Set("PJSIP/357-000632d8", "SHARED(BLKVM,PJSIP/Upstream1-000632cf)=") in new stack
[2024-06-03 12:26:05] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-blkvm-clr:2] Set("PJSIP/357-000632d8", "GOSUB_RETVAL=") in new stack
[2024-06-03 12:26:05] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("PJSIP/357-000632d8", "") in new stack
[2024-06-03 12:26:06] VERBOSE[11765][C-00025afb] app_queue.c: Nobody picked up in 8000 ms
[2024-06-03 12:26:06] VERBOSE[11765][C-00025afb] app_queue.c:     -- LazyMembers debugging - Numbusies: 0, Nummems: 4
[2024-06-03 12:26:06] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-auto-blkvm:8] ExecIf("PJSIP/357-000632d8", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=357/sip:[email protected]:5060)") in new stack
[2024-06-03 12:26:06] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@macro-auto-blkvm:9] ExecIf("PJSIP/357-000632d8", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=)") in new stack
[2024-06-03 12:26:06] VERBOSE[12812][C-00025afb] app_stack.c: PJSIP/357-000632d8 Internal Gosub(post-incomingCall,s,1(s,1)) start
[2024-06-03 12:26:06] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@post-incomingCall:1] NoOp("PJSIP/357-000632d8", "INBOUND - Send Post") in new stack
[2024-06-03 12:26:06] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@post-incomingCall:2] ExecIf("PJSIP/357-000632d8", "0?Goto(call-volume-pickup,s,1)") in new stack
[2024-06-03 12:26:06] VERBOSE[12812][C-00025afb] pbx.c: Executing [s@post-incomingCall:3] GotoIf("PJSIP/357-000632d8", "1?setVar:continue") in new stack

It does seem like it took a second to execute, however in reality it could be that it took a few milliseconds which coincidently also changed form :05 to :06.

BlazeStudios · June 4, 2024, 2:55pm

Go into Settings → Asterisk Logfile settings and change the default date format from %F %T to %F %T.%3q this will give you millisecond output on the timestamps in the log files.

The issue remains the agent is answering the call 7+ seconds into the 8 second ring time. This will give you a better view of how long it is actually taking.

PitzKey · June 4, 2024, 3:56pm

Thank you, added.

PitzKey · June 7, 2024, 2:52pm

Interesting. Seems like 10ms is what has caused this issue, this time.

[2024-06-05 11:05:05.478] VERBOSE[110683][C-0000012e] app_queue.c: Called Local/329@from-queue/n
...
[2024-06-05 11:05:05.509] VERBOSE[112144][C-0000012e] app_dial.c: Called PJSIP/329/sip:[email protected]:5060
[2024-06-05 11:05:05.513] VERBOSE[112144][C-0000012e] app_dial.c: Connected line update to Local/329@from-queue-0000049c;2 prevented.
[2024-06-05 11:05:05.517] VERBOSE[110683][C-0000012e] app_queue.c: Local/329@from-queue-0000049c;1 is ringing
[2024-06-05 11:05:05.673] VERBOSE[112144][C-0000012e] app_dial.c: PJSIP/329-000002c7 is ringing
[2024-06-05 11:05:05.674] VERBOSE[110683][C-0000012e] app_queue.c: Local/329@from-queue-0000049c;1 is ringing
[2024-06-05 11:05:13.467] VERBOSE[112144][C-0000012e] app_dial.c: PJSIP/329-000002c7 answered Local/329@from-queue-0000049c;2
[2024-06-05 11:05:13.468] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-auto-blkvm:1] ExecIf("PJSIP/329-000002c7", "1?Set(CDR(recordingfile)=in-8004448888-2120001111-20240605-110421-1717599861.4373.wav)") in new stack
[2024-06-05 11:05:13.468] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-auto-blkvm:2] Set("PJSIP/329-000002c7", "__MACRO_RESULT=") in new stack
[2024-06-05 11:05:13.468] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-auto-blkvm:3] Set("PJSIP/329-000002c7", "CFIGNORE=") in new stack
[2024-06-05 11:05:13.468] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-auto-blkvm:4] Set("PJSIP/329-000002c7", "MASTER_CHANNEL(CFIGNORE)=") in new stack
[2024-06-05 11:05:13.468] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-auto-blkvm:5] Set("PJSIP/329-000002c7", "FORWARD_CONTEXT=from-internal") in new stack
[2024-06-05 11:05:13.468] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-auto-blkvm:6] Set("PJSIP/329-000002c7", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
[2024-06-05 11:05:13.469] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-auto-blkvm:7] Macro("PJSIP/329-000002c7", "blkvm-clr,") in new stack
[2024-06-05 11:05:13.469] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-blkvm-clr:1] Set("PJSIP/329-000002c7", "SHARED(BLKVM,PJSIP/Upstream1-000002c0)=") in new stack
[2024-06-05 11:05:13.469] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-blkvm-clr:2] Set("PJSIP/329-000002c7", "GOSUB_RETVAL=") in new stack
[2024-06-05 11:05:13.469] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("PJSIP/329-000002c7", "") in new stack
[2024-06-05 11:05:13.469] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-auto-blkvm:8] ExecIf("PJSIP/329-000002c7", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=329/sip:[email protected]:5060)") in new stack
[2024-06-05 11:05:13.469] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@macro-auto-blkvm:9] ExecIf("PJSIP/329-000002c7", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=)") in new stack
[2024-06-05 11:05:13.471] VERBOSE[112144][C-0000012e] app_stack.c: PJSIP/329-000002c7 Internal Gosub(post-incomingCall,s,1(s,1)) start
[2024-06-05 11:05:13.472] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@post-incomingCall:1] NoOp("PJSIP/329-000002c7", "INBOUND - Send Post") in new stack
[2024-06-05 11:05:13.472] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@post-incomingCall:2] ExecIf("PJSIP/329-000002c7", "0?Goto(call-volume-pickup,s,1)") in new stack
[2024-06-05 11:05:13.472] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@post-incomingCall:3] GotoIf("PJSIP/329-000002c7", "1?setVar:continue") in new stack
[2024-06-05 11:05:13.472] VERBOSE[112144][C-0000012e] pbx_builtins.c: Goto (post-incomingCall,s,4)
[2024-06-05 11:05:13.472] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@post-incomingCall:4] Set("PJSIP/329-000002c7", "CallerID=Andrew Ohio") in new stack
[2024-06-05 11:05:13.472] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@post-incomingCall:5] GotoIf("PJSIP/329-000002c7", "0?setVar2:post") in new stack
[2024-06-05 11:05:13.472] VERBOSE[112144][C-0000012e] pbx_builtins.c: Goto (post-incomingCall,s,7)
[2024-06-05 11:05:13.472] VERBOSE[112144][C-0000012e] pbx.c: Executing [s@post-incomingCall:7] System("PJSIP/329-000002c7", "/scripts/post_inbound.sh "Andrew Ohio" 2120001111 329 1717599905.4468 Answered &") in new stack
[2024-06-05 11:05:13.482] VERBOSE[110683][C-0000012e] app_queue.c: Nobody picked up in 8000 ms

BlazeStudios · June 7, 2024, 5:49pm

Yes and no. You have an 8 second timeout for this, and again @jcolp can fill in blanks/corrections, but if we say the counter starts ticking when the queue sends into the dialplan and when the second leg of the local channel is answered:

[2024-06-05 11:05:05.478] VERBOSE[110683][C-0000012e] app_queue.c: Called Local/329@from-queue/n
[2024-06-05 11:05:13.467] VERBOSE[112144][C-0000012e] app_dial.c: PJSIP/329-000002c7 answered Local/329@from-queue-0000049c;2

There’s 1ms left on the 8 second timeout when they answer. It seems that even without the gosub running, etc by the time the 2nd leg of the local channel tells the 1st leg it’s answered the timeout has completed.

Now based on your previous posts, this seems to be an issue with the first agent being called because the previous logs show the second agent answering the calls well under 8 seconds. I guess you need to determine if 8 seconds enough of a timeout based on the ring strategy and the fact the 1st agent has consistently answered these calls just before the timeout expires.

Is the first agent taking a lot of calls? Do you have a wrap-up time set for the agents?