Nobody picked up in 15000 ms but. 2 sec passed only

have a basic queue with rrmemory ring strategy with 15-sec agent timeout

the call sequence involved extension 145 rejecting the call after ringing for 13 seconds. Then, at 08:23:10, the system initiated a call to extension 122. However, at 08:23:12, it was reported that “Nobody picked up in 15000 ms.”
but only 2 seconds had actually elapsed between 08:23:12 and 08:23:10. This raises a discrepancy.

[2023-09-26 08:22:57] VERBOSE[27569][C-00000a6e] app_queue.c: Local/145@from-queue-000006bb;1 is ringing
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] app_dial.c: Everyone is busy/congested at this time (1:1/0/0)
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [s@macro-dial-one:56] ExecIf("Local/145@from-queue-000006bb;2", "0?MacroExit()") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [s@macro-dial-one:57] ExecIf("Local/145@from-queue-000006bb;2", "0?Set(DIALSTATUS=)") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [s@macro-dial-one:58] GosubIf("Local/145@from-queue-000006bb;2", "0?s-BUSY,1()") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [s@macro-dial-one:59] MacroExit("Local/145@from-queue-000006bb;2", "") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [145@from-queue-exten-only:10] GotoIf("Local/145@from-queue-000006bb;2", "0?,,") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [145@from-queue-exten-only:11] Hangup("Local/145@from-queue-000006bb;2", "") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Spawn extension (from-queue-exten-only, 145, 11) exited non-zero on 'Local/145@from-queue-000006bb;2'
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [h@from-queue-exten-only:1] Macro("Local/145@from-queue-000006bb;2", "hangupcall,") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("Local/145@from-queue-000006bb;2", "1?theend") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("Local/145@from-queue-000006bb;2", "0?Set(CDR(recordingfile)=)") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [s@macro-hangupcall:4] Hangup("Local/145@from-queue-000006bb;2", "") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'Local/145@from-queue-000006bb;2' in macro 'hangupcall'
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Spawn extension (from-queue-exten-only, h, 1) exited non-zero on 'Local/145@from-queue-000006bb;2'
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] app_stack.c: Local/145@from-queue-000006bb;2 Internal Gosub(queueMemberCall-hangup,s,1(145,1695741777.8791,805)) start
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [s@queueMemberCall-hangup:1] NoOp("Local/145@from-queue-000006bb;2", "145") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [s@queueMemberCall-hangup:2] UserEvent("Local/145@from-queue-000006bb;2", "QueueMemberCallHangup,QAGENT:145,UNIQ:1695741777.8791,Queue:805,DIALSTATUS:BUSY") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] pbx.c: Executing [s@queueMemberCall-hangup:3] Return("Local/145@from-queue-000006bb;2", "") in new stack
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] app_stack.c: Spawn extension (from-queue-exten-only, h, 1) exited non-zero on 'Local/145@from-queue-000006bb;2'
[2023-09-26 08:23:10] VERBOSE[27577][C-00000a6e] app_stack.c: Local/145@from-queue-000006bb;2 Internal Gosub(queueMemberCall-hangup,s,1(145,1695741777.8791,805)) complete GOSUB_RETVAL=
[2023-09-26 08:23:10] VERBOSE[27578][C-00000a6e] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2023-09-26 08:23:10] VERBOSE[27578][C-00000a6e] app_mixmonitor.c: End MixMonitor Recording Local/145@from-queue-000006bb;2
[2023-09-26 08:23:10] VERBOSE[27569][C-00000a6e] app_queue.c: Nobody picked up in 13000 ms
[2023-09-26 08:23:10] VERBOSE[27569][C-00000a6e] app_queue.c: Called Local/122@from-queue/n
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue:1] Set("Local/122@from-queue-000006bc;2", "QAGENT=122") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue:2] Set("Local/122@from-queue-000006bc;2", "__FROMQ=true") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue:3] UserEvent("Local/122@from-queue-000006bc;2", "QueueMemberCallDial,QAGENT:122,UNIQ:1695741790.8794,Queue:805,LinkedID:") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue:4] Set("Local/122@from-queue-000006bc;2", "CHANNEL(hangup_handler_push)=queueMemberCall-hangup,s,1(122,1695741790.8794,805)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue:5] GotoIf("Local/122@from-queue-000006bc;2", "0?hangup") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue:6] GotoIf("Local/122@from-queue-000006bc;2", "1?805,1:hangup") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (from-queue,805,1)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [805@from-queue:1] Goto("Local/122@from-queue-000006bc;2", "from-queue-exten-only,122,1") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (from-queue-exten-only,122,1)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue-exten-only:1] GotoIf("Local/122@from-queue-000006bc;2", "0?hangup") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue-exten-only:2] GotoIf("Local/122@from-queue-000006bc;2", "0?from-queue-exten-only-x,122,1") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue-exten-only:3] Set("Local/122@from-queue-000006bc;2", "RingGroupMethod=none") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue-exten-only:4] Set("Local/122@from-queue-000006bc;2", "CHANNEL(language)=en") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue-exten-only:5] Set("Local/122@from-queue-000006bc;2", "QDOPTS=") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue-exten-only:6] Set("Local/122@from-queue-000006bc;2", "CALLTYPE_OVERRIDE=external") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue-exten-only:7] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(FROMEXTEN=805)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue-exten-only:8] Gosub("Local/122@from-queue-000006bc;2", "sub-record-check,s,1(exten,122,)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@sub-record-check:1] GotoIf("Local/122@from-queue-000006bc;2", "10?initialized") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (sub-record-check,s,10)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@sub-record-check:10] NoOp("Local/122@from-queue-000006bc;2", "Recordings initialized") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@sub-record-check:11] ExecIf("Local/122@from-queue-000006bc;2", "1?Set(ARG3=dontcare)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@sub-record-check:12] Set("Local/122@from-queue-000006bc;2", "REC_POLICY_MODE_SAVE=") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@sub-record-check:13] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(REC_STATUS=NO)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@sub-record-check:14] GotoIf("Local/122@from-queue-000006bc;2", "5?checkaction") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (sub-record-check,s,17)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@sub-record-check:17] GotoIf("Local/122@from-queue-000006bc;2", "1?sub-record-check,exten,1") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [exten@sub-record-check:1] NoOp("Local/122@from-queue-000006bc;2", "Exten Recording Check between 9312008023 and 122") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [exten@sub-record-check:2] Set("Local/122@from-queue-000006bc;2", "CALLTYPE=external") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [exten@sub-record-check:3] ExecIf("Local/122@from-queue-000006bc;2", "8?Set(CALLTYPE=external)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [exten@sub-record-check:4] Set("Local/122@from-queue-000006bc;2", "CALLEE=yes") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [exten@sub-record-check:5] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(CALLEE=dontcare)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [exten@sub-record-check:6] GotoIf("Local/122@from-queue-000006bc;2", "1?callee") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (sub-record-check,exten,11)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [exten@sub-record-check:11] Gosub("Local/122@from-queue-000006bc;2", "recordcheck,1(yes,external,122)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("Local/122@from-queue-000006bc;2", "Starting recording check against yes") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("Local/122@from-queue-000006bc;2", "yes") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (sub-record-check,recordcheck,9)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:9] ExecIf("Local/122@from-queue-000006bc;2", "0?Return()") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:10] Set("Local/122@from-queue-000006bc;2", "__REC_POLICY_MODE=YES") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:11] Goto("Local/122@from-queue-000006bc;2", "startrec") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (sub-record-check,recordcheck,16)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp("Local/122@from-queue-000006bc;2", "Starting recording: external, 122") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:17] ExecIf("Local/122@from-queue-000006bc;2", "1?Set(RECFROMEXTEN=9312008023)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:18] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(RECFROMEXTEN=9312008023)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:19] Set("Local/122@from-queue-000006bc;2", "__CALLFILENAME=external-122-9312008023-20230926-082257-1695741790.8794") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:20] MixMonitor("Local/122@from-queue-000006bc;2", "2023/09/26/external-122-9312008023-20230926-082257-1695741790.8794.WAV,abi(),") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:21] Set("Local/122@from-queue-000006bc;2", "__MIXMON_ID=") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:22] Set("Local/122@from-queue-000006bc;2", "__RECORD_ID=Local/122@from-queue-000006bc;2") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:23] Set("Local/122@from-queue-000006bc;2", "__REC_STATUS=RECORDING") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:24] Set("Local/122@from-queue-000006bc;2", "CDR(recordingfile)=external-122-9312008023-20230926-082257-1695741790.8794.WAV") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [recordcheck@sub-record-check:25] Return("Local/122@from-queue-000006bc;2", "") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [exten@sub-record-check:12] Return("Local/122@from-queue-000006bc;2", "") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [122@from-queue-exten-only:9] Macro("Local/122@from-queue-000006bc;2", "dial-one,,HhTtr,122") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:1] Set("Local/122@from-queue-000006bc;2", "DEXTEN=122") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:2] ExecIf("Local/122@from-queue-000006bc;2", "1?Set(__EXTTOCALL=122)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:3] Set("Local/122@from-queue-000006bc;2", "DIALSTATUS_CW=") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:4] GosubIf("Local/122@from-queue-000006bc;2", "0?screen,1()") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:5] GosubIf("Local/122@from-queue-000006bc;2", "0?cf,1()") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:6] GotoIf("Local/122@from-queue-000006bc;2", "1?skip1") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (macro-dial-one,s,9)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:9] GotoIf("Local/122@from-queue-000006bc;2", "0?nodial") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:10] GotoIf("Local/122@from-queue-000006bc;2", "0?continue") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:11] Set("Local/122@from-queue-000006bc;2", "EXTHASCW=") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:12] GotoIf("Local/122@from-queue-000006bc;2", "1?next1:cwinusebusy") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (macro-dial-one,s,13)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:13] GotoIf("Local/122@from-queue-000006bc;2", "0?docfu:skip3") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (macro-dial-one,s,17)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:17] GotoIf("Local/122@from-queue-000006bc;2", "1?next2:continue") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (macro-dial-one,s,18)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:18] GotoIf("Local/122@from-queue-000006bc;2", "1?continue") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (macro-dial-one,s,26)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:26] GotoIf("Local/122@from-queue-000006bc;2", "0?nodial") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:27] GosubIf("Local/122@from-queue-000006bc;2", "1?dstring,1():dlocal,1()") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:1] Set("Local/122@from-queue-000006bc;2", "DSTRING=") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:2] Set("Local/122@from-queue-000006bc;2", "DEVICES=122") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf("Local/122@from-queue-000006bc;2", "0?Return()") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(DEVICES=22)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:5] Set("Local/122@from-queue-000006bc;2", "LOOPCNT=1") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:6] Set("Local/122@from-queue-000006bc;2", "ITER=1") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:7] Set("Local/122@from-queue-000006bc;2", "THISDIAL=PJSIP/122") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:8] GotoIf("Local/122@from-queue-000006bc;2", "0?docheck") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:9] NoOp("Local/122@from-queue-000006bc;2", "Debug: Found PJSIP Destination PJSIP/122") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:10] GotoIf("Local/122@from-queue-000006bc;2", "0?doset") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:11] NoOp("Local/122@from-queue-000006bc;2", "Debug: Updating PJSIP Destination with PJSIP_DIAL_CONTACTS") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:12] Set("Local/122@from-queue-000006bc;2", "THISDIAL=PJSIP/122/sip:[email protected]:56790;transport=TCP;x-ast-orig-host=10.0.0.139:5062") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:13] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(DIALSTATUS=CHANUNAVAIL)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:14] GotoIf("Local/122@from-queue-000006bc;2", "0?skipset") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:15] Set("Local/122@from-queue-000006bc;2", "DSTRING=PJSIP/122/sip:[email protected]:56790;transport=TCP;x-ast-orig-host=10.0.0.139:5062&") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:16] Set("Local/122@from-queue-000006bc;2", "ITER=2") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:17] GotoIf("Local/122@from-queue-000006bc;2", "0?begin") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:18] ExecIf("Local/122@from-queue-000006bc;2", "0?Return()") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:19] Set("Local/122@from-queue-000006bc;2", "DSTRING=PJSIP/122/sip:[email protected]:56790;transport=TCP;x-ast-orig-host=10.0.0.139:5062") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [dstring@macro-dial-one:20] Return("Local/122@from-queue-000006bc;2", "") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:28] GotoIf("Local/122@from-queue-000006bc;2", "0?nodial") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:29] GotoIf("Local/122@from-queue-000006bc;2", "0?skiptrace") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:30] GosubIf("Local/122@from-queue-000006bc;2", "1?ctset,1():ctclear,1()") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [ctset@macro-dial-one:1] Set("Local/122@from-queue-000006bc;2", "DB(CALLTRACE/122)=9312008023") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [ctset@macro-dial-one:2] Return("Local/122@from-queue-000006bc;2", "") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:31] Set("Local/122@from-queue-000006bc;2", "D_OPTIONS=HhTtrM(auto-blkvm)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:32] GosubIf("Local/122@from-queue-000006bc;2", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:33] NoOp("Local/122@from-queue-000006bc;2", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:34] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(ALERT_INFO=)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:35] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(ALERT_INFO=)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:36] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(ALERT_INFO=)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:37] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:38] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:39] GosubIf("Local/122@from-queue-000006bc;2", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:40] ExecIf("Local/122@from-queue-000006bc;2", "1?Set(CHANNEL(musicclass)=96425Greet)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:41] GosubIf("Local/122@from-queue-000006bc;2", "0?qwait,1()") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:42] Set("Local/122@from-queue-000006bc;2", "__CWIGNORE=TRUE") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:43] Set("Local/122@from-queue-000006bc;2", "__KEEPCID=TRUE") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:44] GotoIf("Local/122@from-queue-000006bc;2", "0?usegoto,1") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:45] GotoIf("Local/122@from-queue-000006bc;2", "1?godial") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx_builtins.c: Goto (macro-dial-one,s,50)
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:50] Macro("Local/122@from-queue-000006bc;2", "dialout-one-predial-hook,") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit("Local/122@from-queue-000006bc;2", "") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:51] ExecIf("Local/122@from-queue-000006bc;2", "1?Set(D_OPTIONS=HhtrM(auto-blkvm)I)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:52] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(CWRING=r(callwaiting)):Set(CWRING=)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:53] NoOp("Local/122@from-queue-000006bc;2", "") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:54] ExecIf("Local/122@from-queue-000006bc;2", "0?Set(D_OPTIONS=HhtrM(auto-blkvm)Ig)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@macro-dial-one:55] Dial("Local/122@from-queue-000006bc;2", "PJSIP/122/sip:[email protected]:56790;transport=TCP;x-ast-orig-host=10.0.0.139:5062,,HhtrM(auto-blkvm)Ib(func-apply-sipheaders^s^1)") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] app_stack.c: PJSIP/122-000013a6 Internal Gosub(func-apply-sipheaders,s,1) start
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("PJSIP/122-000013a6", "Applying SIP Headers to channel PJSIP/122-000013a6") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@func-apply-sipheaders:2] Set("PJSIP/122-000013a6", "TECH=PJSIP") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/122-000013a6", "SIPHEADERKEYS=") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@func-apply-sipheaders:4] While("PJSIP/122-000013a6", "0") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] app_while.c: Jumping to priority 12
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] pbx.c: Executing [s@func-apply-sipheaders:13] Return("PJSIP/122-000013a6", "") in new stack
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] app_stack.c: Spawn extension (from-internal, 122, 1) exited non-zero on 'PJSIP/122-000013a6'
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] app_stack.c: PJSIP/122-000013a6 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] app_dial.c: Called PJSIP/122/sip:[email protected]:56790;transport=TCP;x-ast-orig-host=10.0.0.139:5062
[2023-09-26 08:23:10] VERBOSE[27569][C-00000a6e] app_queue.c: Local/122@from-queue-000006bc;1 is ringing
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] app_dial.c: Connected line update to Local/122@from-queue-000006bc;2 prevented.
[2023-09-26 08:23:10] VERBOSE[27736][C-00000a6e] app_mixmonitor.c: Begin MixMonitor Recording Local/122@from-queue-000006bc;2
[2023-09-26 08:23:10] VERBOSE[27735][C-00000a6e] app_dial.c: PJSIP/122-000013a6 is ringing
[2023-09-26 08:23:10] VERBOSE[27569][C-00000a6e] app_queue.c: Local/122@from-queue-000006bc;1 is ringing
[2023-09-26 08:23:12] VERBOSE[27569][C-00000a6e] app_queue.c: Nobody picked up in 15000 ms
[2023-09-26 08:23:12] VERBOSE[27735][C-00000a6e] app_macro.c: Spawn extension (macro-dial-one, s, 55) exited non-zero on 'Local/122@from-queue-000006bc;2' in macro 'dial-one'

Could just be the way the NoOps are written. Did was 122 not in a position to answer? If you wanted to look at “correcting” this, you would need to submist a bug report.

System Dashboard - Sangoma Issue Tracker (freepbx.org)

@comtech thanks for reply
Based on the screen, it displayed “REC” on the agent’s workplace. She was prepared to answer a call, but the indicator only flashed briefly, and she couldn’t even select the button to answer it. This issue arose on Asterisk 16.24. I’ve noticed there’s a 16.30 upgrade available, so I upgrated. I’m currently awaiting another incident before submitting a ticket.

1 Like

Can you please provide a full call trace?

grep C-00000a6e /var/log/asterisk/full* | pastebin

https://pastebin.com/raw/1Ki68xKE

This is indeed an interesting one. This looks like rather an Asterisk bug than a FreePBX bug.

Can you please provide the Asterisk version as well as the actual queue config from the conf file?

A ticket won’t be accepted against Asterisk 16 as it is not a security issue, and Asterisk 16 is on security fixes only. Security issues may not get applied either, as it transitions to end of life next month and there may not be enough time to turn the handle before then.

Curiosity: what do you get on the queue_log file?


queue says the same " ```
Nobody picked up in 15000 ms

but  2 seconds  are passed only between 2  events

16.24 as i told in prev reply

It looks like the first two agent rings happen in parallel… and weirdly one timeouts in 13 and the other in 15 seconds.

Sorry I missed that.

Asterisk 16 is in security fix only and will be EOL in less than a month. Asterisk Versions - Asterisk Documentation

Try switching to Asterisk 18 or 20.

asterisk-version-switch

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