Channel.c: Exceptionally long voice queue length queuing to Local

Asterisk Asterisk Support
1

Hello, everyone.
I have to dial the local channel, because I need music on hold to run smoothly. Occasionally I get “Exceptionally long voice queue length queuing to Local”, and then I see lost packets with pjsip show channelstats. How can I get rid of this error? I get this error when the other side answers and local channels merge with PJSIP channels.

The asterisk machine is 5 meters away from the partner SBS firewall and connected to it directly. I think there should be no lost packages. There emerge only in bridged calls. When a caller goes through an IVR menu, everything is okey.

2

I suspect there is something with my dialplan. Here it is:

[call-client]
exten => s,1,NoOp(Call client)
same => n,Set(__call_protocol=PJSIP)
same => n,Set(__call_trunk=si3000)
same => n,Set(__redir_num=83952450439)
same => n,Set(dnid=${CUT(CALLERID(dnid),;,1)})

same => n,Set(__orig_num={IF([{LEN({CALLERID(RDNIS)})}>0]?{CALLERID(RDNIS)}:{orig_num})})
same => n,Set(__orig_num={IF([{LEN({REDIRECTING(orig-num)})}>0]?{REDIRECTING(orig-num)}:{orig_num})})
same => n,Set(__orig_num={IF([{LEN({orig_num})}=0&{redir_num}!={dnid}]?{dnid}:{orig_num})})

same => n,Set(DEFAULT_MUSIC_ON_HOLD=irkdefault)
same => n,Set(DEFAULT_BUSY_FILE=busy_default)
same => n,Set(DEFAULT_NOANSWER_FILE=noanswer_default)
same => n,Set(__phones={ARG1}) ; phones, arg2 same => n,Set(timeout={IF([{ISNULL({ARG2})}=1]?180:{ARG2})}) ; total call time, arg2
same => n,Set(__trial_timeout={IF([{ISNULL({ARG3})}=1]?30:{ARG3})}) ; trial time, arg3 same => n,Set(play_moh={IF([{ISNULL({ARG4})}=1]?0:{ARG4})}); play moh, arg 4
same => n,Set(moh={IF([{ISNULL({ARG5})}=1]?{DEFAULT_MUSIC_ON_HOLD}:{ARG5})}) ; moh file, arg5
same => n,Set(__say_busy={IF([{ISNULL({ARG6})}=1]?0:{ARG6})}); - play busy message, arg6 same => n,Set(busy_file={IF([{ISNULL({ARG7})}=1]?busy/{DEFAULT_BUSY_FILE}:busy/{ARG7})}) ; busy message file, arg7 same => n,Set(return_back={IF([{ISNULL({ARG8})}=1]?0:{ARG8})}) ; return to previous context, arg8
same => n,Set(say_noanswer={IF([{ISNULL({ARG9})}=1]?0:{ARG9})}) ; play noanswer file, arg9 same => n,Set(noanswer_file={IF([{ISNULL({ARG10})}=1]?{DEFAULT_NOANSWER_FILE}:{ARG10})}) ; noanswer file, arg10 same => n,Set(make_pause={IF([{ISNULL({ARG11})}=1]?1:{ARG11})});

same => n,Set(dial_options=)
same => n,ExecIf([{play_moh}=1]?Set(dial_options=[{dial_options}m({moh})]):Set(dial_options=[{dial_options}r]))

same => n,Set(__phones_busy={IF([{say_busy}=1]?1:0)}) same => n,Set(__phones_problem=1) same => n,Set(__call_end_time=[{EPOCH}+{timeout}])
same => n,ExecIf([{make_pause}=1]?Wait(0.2))
same => n(dial),Dial(Local/s@call-client-phones,{timeout},{dial_options})
same => n(afterdial),GoToIf([{phones_busy}=1]?busy:noanswer)
same => n(busy),Wait(0.5)
same => n,Playback(${busy_file})
same => n,Set(__phones_busy=0)
same => n,Wait(0.2)
;same => n,Set(__phones_busy=0)
same => n,GoTo(dial)

same => n(noanswer),NoOp(Cancelling call)
same => n,Wait(0.5)
same => n,ExecIf([{say_noanswer}=1]?Playback(noanswer/{noanswer_file})) same => n,ExecIf([${return_back}=1]?Return():HangUp())

[call-client-phones]
exten => s,1,Set(cphones={phones}) same => n(whl),While(["{SET(cl_i={SHIFT(cphones,+)})}" !=""])
same => n,Set(cl_ph=)
same => n,While(["{SET(cl_phi={SHIFT(cl_i,&)})}" !=""]) same => n,Set(cl_ph={IF([{ISNULL({cl_ph})}=1]?{call_protocol}/{cl_phi}@{call_trunk}:{cl_ph}&{call_protocol}/{cl_phi}@{call_trunk})})
same => n,EndWhile()
same => n,Dial({cl_ph},{trial_timeout},b(add-diversion-header^s^1({redir_num},{orig_num})))
same => n,Set(phones_busy={IF([{DIALSTATUS}=BUSY&{phones_busy}=1]?1:0)})
same => n,EndWhile()
same => n,Set(cphones={phones}) same => n,ExecIf([{phones_busy}=0]?GoTo(phones_free)) same => n,Hangup() ;same => n(phones_free),ExecIf([{call_end_time}<{EPOCH}]?HangUp())
same => n(phones_free),Wait(2)
same => n,GoToIf([{DIALSTATUS}=BUSY|${DIALSTATUS}=NOANSWER]?whl)

3

What is the actual console output when it occurs?

4

For example,

2019-06-24 19:28:55] VERBOSE[23201] netsock2.c: Using SIP RTP Audio TOS bits 184
[2019-06-24 19:28:55] VERBOSE[23201] netsock2.c: Using SIP RTP Audio CoS mark 5
[2019-06-24 19:28:56] VERBOSE[8988][C-000002ec] app_dial.c: PJSIP/si3000-00000595 is ringing
[2019-06-24 19:28:56] VERBOSE[8986][C-000002ec] app_dial.c: Local/s@call-client-phones-00000191;1 is ringing
[2019-06-24 19:28:56] VERBOSE[8988][C-000002ec] app_dial.c: PJSIP/si3000-00000595 is ringing
[2019-06-24 19:28:58] VERBOSE[8988][C-000002ec] app_dial.c: PJSIP/si3000-00000595 answered Local/s@call-client-phones-00000191;2
[2019-06-24 19:28:58] VERBOSE[8986][C-000002ec] app_dial.c: Local/s@call-client-phones-00000191;1 answered PJSIP/si3000-00000594
[2019-06-24 19:28:58] VERBOSE[8986][C-000002ec] res_musiconhold.c: Stopped music on hold on PJSIP/si3000-00000594
[2019-06-24 19:28:58] VERBOSE[8989][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000595 joined ‘simple_bridge’ basic-bridge
[2019-06-24 19:28:58] VERBOSE[8990][C-000002ec] bridge_channel.c: Channel Local/s@call-client-phones-00000191;1 joined ‘simple_bridge’ basic-bridge <6520bed9-7b2c-4ffe-9d13-a707ba1c706f>
[2019-06-24 19:28:58] VERBOSE[8988][C-000002ec] bridge_channel.c: Channel Local/s@call-client-phones-00000191;2 joined ‘simple_bridge’ basic-bridge
[2019-06-24 19:28:58] VERBOSE[8986][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000594 joined ‘simple_bridge’ basic-bridge <6520bed9-7b2c-4ffe-9d13-a707ba1c706f>
[2019-06-24 19:28:58] WARNING[8988][C-000002ec] channel.c: Exceptionally long voice queue length queuing to Local/s@call-client-phones-00000191;1
[2019-06-24 19:28:58] VERBOSE[8990][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000594 left ‘simple_bridge’ basic-bridge <6520bed9-7b2c-4ffe-9d13-a707ba1c706f>
[2019-06-24 19:28:58] VERBOSE[8990][C-000002ec] bridge_channel.c: Channel Local/s@call-client-phones-00000191;2 left ‘simple_bridge’ basic-bridge
[2019-06-24 19:28:58] VERBOSE[8990][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000594 swapped with Local/s@call-client-phones-00000191;2 into ‘simple_bridge’ basic-bridge
[2019-06-24 19:28:58] VERBOSE[8990][C-000002ec] bridge_channel.c: Channel Local/s@call-client-phones-00000191;1 left ‘simple_bridge’ basic-bridge <6520bed9-7b2c-4ffe-9d13-a707ba1c706f>
[2019-06-24 19:28:58] VERBOSE[8988][C-000002ec] pbx.c: Spawn extension (call-client-phones, s, 7) exited non-zero on ‘Local/s@call-client-phones-00000191;2’
[2019-06-24 19:29:11] VERBOSE[8986][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000594 left ‘simple_bridge’ basic-bridge
[2019-06-24 19:29:11] VERBOSE[8989][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000595 left ‘simple_bridge’ basic-bridge

5

That doesn’t seem to include the full dialplan execution. Can you also show that?

6

[2019-06-24 19:28:41] VERBOSE[23201] pbx_variables.c: Setting global variable ‘SIPDOMAIN’ to ‘172.16.128.102’
[2019-06-24 19:28:41] VERBOSE[23201] netsock2.c: Using SIP RTP Audio TOS bits 184
[2019-06-24 19:28:41] VERBOSE[23201] netsock2.c: Using SIP RTP Audio CoS mark 5
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483;tgrp=14;trunk-context=172.16.255.17@from-pjsip:1] NoOp(“PJSIP/si3000-00000594”, “Test”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483;tgrp=14;trunk-context=172.16.255.17@from-pjsip:2] Set(“PJSIP/si3000-00000594”, “t=“83952450483” sip:83952450483@172.16.128.102;user=phone”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483;tgrp=14;trunk-context=172.16.255.17@from-pjsip:3] NoOp(“PJSIP/si3000-00000594”, ““83952450483” sip:83952450483@172.16.128.102;user=phone”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483;tgrp=14;trunk-context=172.16.255.17@from-pjsip:4] Set(“PJSIP/si3000-00000594”, “p=83952450483”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483;tgrp=14;trunk-context=172.16.255.17@from-pjsip:5] NoOp(“PJSIP/si3000-00000594”, “DID: 83952450483”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483;tgrp=14;trunk-context=172.16.255.17@from-pjsip:6] NoOp(“PJSIP/si3000-00000594”, “CALLERID: 83952450483;tgrp=14;trunk-context=172.16.255.17”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483;tgrp=14;trunk-context=172.16.255.17@from-pjsip:7] Gosub(“PJSIP/si3000-00000594”, “from-pstn,83952450483,1”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:1] Set(“PJSIP/si3000-00000594”, “__DIRECTION=INBOUND”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:2] Gosub(“PJSIP/si3000-00000594”, “sub-record-check,s,1(in,83952450483,yes)”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:1] GotoIf(“PJSIP/si3000-00000594”, “0?initialized”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:2] Set(“PJSIP/si3000-00000594”, “__REC_STATUS=INITIALIZED”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:3] Set(“PJSIPa/si3000-00000594”, “NOW=1561375721”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:4] Set(“PJSIP/si3000-00000594”, “__DAY=24”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:5] Set(“PJSIP/si3000-00000594”, “__MONTH=06”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:6] Set(“PJSIP/si3000-00000594”, “__YEAR=2019”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:7] Set(“PJSIP/si3000-00000594”, “__TIMESTR=20190624-192841”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:8] Set(“PJSIP/si3000-00000594”, “__FROMEXTEN=unknown”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:9] Set(“PJSIP/si3000-00000594”, “__MON_FMT=wav”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:10] NoOp(“PJSIP/si3000-00000594”, “Recordings initialized”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:11] ExecIf(“PJSIP/si3000-00000594”, “0?Set(ARG3=dontcare)”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:12] Set(“PJSIP/si3000-00000594”, “REC_POLICY_MODE_SAVE=”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:13] ExecIf(“PJSIP/si3000-00000594”, “0?Set(REC_STATUS=NO)”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:14] GotoIf(“PJSIP/si3000-00000594”, “2?checkaction”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@sub-record-check:17] GotoIf(“PJSIP/si3000-00000594”, “1?sub-record-check,in,1”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx_builtins.c: Goto (sub-record-check,in,1)
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [in@sub-record-check:1] NoOp(“PJSIP/si3000-00000594”, “Inbound Recording Check to 83952450483”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [in@sub-record-check:2] Set(“PJSIP/si3000-00000594”, “FROMEXTEN=unknown”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [in@sub-record-check:3] ExecIf(“PJSIP/si3000-00000594”, “11?Set(FROMEXTEN=89041443XXX)”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [in@sub-record-check:4] Gosub(“PJSIP/si3000-00000594”, “recordcheck,1(yes,in,83952450483)”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“PJSIP/si3000-00000594”, “Starting recording check against yes”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“PJSIP/si3000-00000594”, “yes”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx_builtins.c: Goto (sub-record-check,recordcheck,9)
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:9] ExecIf(“PJSIP/si3000-00000594”, “0?Return()”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:10] Set(“PJSIP/si3000-00000594”, “__REC_POLICY_MODE=YES”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:11] Goto(“PJSIP/si3000-00000594”, “startrec”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx_builtins.c: Goto (sub-record-check,recordcheck,16)
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:16] NoOp(“PJSIP/si3000-00000594”, “Starting recording: in, 83952450483”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:17] Set(“PJSIP/si3000-00000594”, “__CALLFILENAME=in-83952450483-89041443XXX-20190624-192841-1561375721.2230”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:18] MixMonitor(“PJSIP/si3000-00000594”, “2019/06/24/in-83952450483-89041443XXX-20190624-192841-1561375721.2230.wav,abi(LOCAL_MIXMON_ID),”) in
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:19] Set(“PJSIP/si3000-00000594”, “__MIXMON_ID=0x7fd3d4023480”) in new stack
[2019-06-24 19:28:41] VERBOSE[8987][C-000002ec] app_mixmonitor.c: Begin MixMonitor Recording PJSIP/si3000-00000594
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:20] Set(“PJSIP/si3000-00000594”, “__RECORD_ID=PJSIP/si3000-00000594”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:21] Set(“PJSIP/si3000-00000594”, “__REC_STATUS=RECORDING”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:22] Set(“PJSIP/si3000-00000594”, “CDR(recordingfile)=in-83952450483-89041443XXX-20190624-192841-1561375721.2230.wav”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [recordcheck@sub-record-check:23] Return(“PJSIP/si3000-00000594”, “”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [in@sub-record-check:5] Return(“PJSIP/si3000-00000594”, “”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:3] Set(“PJSIP/si3000-00000594”, “CHANNEL(tonezone)=ru”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:4] Set(“PJSIP/si3000-00000594”, “__FROM_DID=83952450483”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:5] Set(“PJSIP/si3000-00000594”, “returnhere=1”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:6] Gosub(“PJSIP/si3000-00000594”, “app-blacklist-check,s,1()”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“PJSIP/si3000-00000594”, “0?blacklisted”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@app-blacklist-check:2] Set(“PJSIP/si3000-00000594”, “CALLED_BLACKLIST=1”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@app-blacklist-check:3] Return(“PJSIP/si3000-00000594”, “”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:7] Set(“PJSIP/si3000-00000594”, “CDR(did)=83952450483”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:8] GotoIf(“PJSIP/si3000-00000594”, “0?”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:9] ExecIf(“PJSIP/si3000-00000594”, “0 ?Set(CALLERID(name)=89041443XXX)”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:10] Set(“PJSIP/si3000-00000594”, “__MOHCLASS=”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:11] Set(“PJSIP/si3000-00000594”, “__REVERSAL_REJECT=FALSE”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:12] GotoIf(“PJSIP/si3000-00000594”, “1?post-reverse-charge”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx_builtins.c: Goto (from-pstn,83952450483,14)
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:14] NoOp(“PJSIP/si3000-00000594”, “”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:15] Set(“PJSIP/si3000-00000594”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:16] Set(“PJSIP/si3000-00000594”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:17] Set(“PJSIP/si3000-00000594”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:18] Set(“PJSIP/si3000-00000594”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:19] NoOp(“PJSIP/si3000-00000594”, “CallerID Entry Point”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [83952450483@from-pstn:20] Goto(“PJSIP/si3000-00000594”, “450483-CoolShop,s,1”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx_builtins.c: Goto (450483-CoolShop,s,1)
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@450483-CoolShop:1] NoOp(“PJSIP/si3000-00000594”, “CoolShop”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@450483-CoolShop:2] Set(“PJSIP/si3000-00000594”, “CONNECTEDLINE(name,i)=CoolShop”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@450483-CoolShop:3] Set(“PJSIP/si3000-00000594”, “CONNECTEDLINE(name-pres,i)=allowed”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@450483-CoolShop:4] Set(“PJSIP/si3000-00000594”, “CONNECTEDLINE(num,i)=83952450483”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@450483-CoolShop:5] Set(“PJSIP/si3000-00000594”, “CONNECTEDLINE(num-pres)=allowed”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@450483-CoolShop:6] Answer(“PJSIP/si3000-00000594”, “”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@450483-CoolShop:7] Set(“PJSIP/si3000-00000594”, “FD=clients/450483_CoolShop”) in new stack
[2019-06-24 19:28:41] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@450483-CoolShop:8] Wait(“PJSIP/si3000-00000594”, “2”) in new stack
[2019-06-24 19:28:43] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@450483-CoolShop:9] Playback(“PJSIP/si3000-00000594”, “clients/450483_CoolShop/p”) in new stack
[2019-06-24 19:28:43] VERBOSE[8986][C-000002ec] file.c: <PJSIP/si3000-00000594> Playing ‘clients/450483_CoolShop/p.alaw’ (language ‘ru’)
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@450483-CoolShop:10] Gosub(“PJSIP/si3000-00000594”, “call-client,s,1(839522XXXXX+839522XXXXX,300,12,1,450483CoolShop,1,0,1,0.5)”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:1] NoOp(“PJSIP/si3000-00000594”, “Call client”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:2] Set(“PJSIP/si3000-00000594”, “__call_protocol=PJSIP”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:3] Set(“PJSIP/si3000-00000594”, “__call_trunk=si3000”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:4] Set(“PJSIP/si3000-00000594”, “__redir_num=83952450439”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:5] Set(“PJSIP/si3000-00000594”, “dnid=83952450483”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:6] Set(“PJSIP/si3000-00000594”, “__orig_num=839522XXXXX”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:7] Set(“PJSIP/si3000-00000594”, “__orig_num=839522XXXXX”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:8] Set(“PJSIP/si3000-00000594”, “__orig_num=839522XXXXX”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:9] Set(“PJSIP/si3000-00000594”, “DEFAULT_MUSIC_ON_HOLD=irkdefault”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:10] Set(“PJSIP/si3000-00000594”, “DEFAULT_BUSY_FILE=busy_default”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:11] Set(“PJSIP/si3000-00000594”, “DEFAULT_NOANSWER_FILE=noanswer_default”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:12] Set(“PJSIP/si3000-00000594”, “__phones=839522XXXXX+839522XXXXX”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:13] Set(“PJSIP/si3000-00000594”, “timeout=300”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:14] Set(“PJSIP/si3000-00000594”, “__trial_timeout=12”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:15] Set(“PJSIP/si3000-00000594”, “play_moh=1”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:16] Set(“PJSIP/si3000-00000594”, “moh=450483CoolShop”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:17] Set(“PJSIP/si3000-00000594”, “__say_busy=1”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:18] Set(“PJSIP/si3000-00000594”, “busy_file=busy/busy_default”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:19] Set(“PJSIP/si3000-00000594”, “return_back=0”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:20] Set(“PJSIP/si3000-00000594”, “say_noanswer=1”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:21] Set(“PJSIP/si3000-00000594”, “noanswer_file=noanswer_default”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:22] Set(“PJSIP/si3000-00000594”, “make_pause=0.5”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:23] Set(“PJSIP/si3000-00000594”, “dial_options=”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:24] ExecIf(“PJSIP/si3000-00000594”, “1?Set(dial_options=[m(450483CoolShop)]):Set(dial_options=r)”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:25] Set(“PJSIP/si3000-00000594”, “__phones_busy=1”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:26] Set(“PJSIP/si3000-00000594”, “__phones_problem=1”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:27] Set(“PJSIP/si3000-00000594”, “__call_end_time=1561376034”) in new stack
[2019-06-24 19:28:54] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:28] ExecIf(“PJSIP/si3000-00000594”, “1?Wait(0.5)”) in new stack
[2019-06-24 19:28:55] VERBOSE[8986][C-000002ec] pbx.c: Executing [s@call-client:29] Dial(“PJSIP/si3000-00000594”, “Local/s@call-client-phones,300,[m(450483CoolShop)]”) in new stack
[2019-06-24 19:28:55] VERBOSE[8986][C-000002ec] app_dial.c: Called Local/s@call-client-phones
[2019-06-24 19:28:55] VERBOSE[8986][C-000002ec] res_musiconhold.c: Started music on hold, class ‘450483CoolShop’, on channel ‘PJSIP/si3000-00000594’
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@call-client-phones:1] Set(“Local/s@call-client-phones-00000191;2”, “cphones=839522XXXXX+839522XXXXX”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@call-client-phones:2] While(“Local/s@call-client-phones-00000191;2”, “1”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@call-client-phones:3] Set(“Local/s@call-client-phones-00000191;2”, “cl_ph=”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@call-client-phones:4] While(“Local/s@call-client-phones-00000191;2”, “1”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@call-client-phones:5] Set(“Local/s@call-client-phones-00000191;2”, “cl_ph=PJSIP/839522XXXXX@si3000”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@call-client-phones:6] EndWhile(“Local/s@call-client-phones-00000191;2”, “”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@call-client-phones:4] While(“Local/s@call-client-phones-00000191;2”, “0”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@call-client-phones:7] Dial(“Local/s@call-client-phones-00000191;2”, “PJSIP/839522XXXXX@si3000,12,b(add-diversion-header^s^1(83952450439,839522XXXXX))”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] app_stack.c: PJSIP/si3000-00000595 Internal Gosub(add-diversion-header,s,1(83952450439,839522XXXXX)) start
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@add-diversion-header:1] NoOp(“PJSIP/si3000-00000595”, “Diversion”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@add-diversion-header:2] Set(“PJSIP/si3000-00000595”, “phoneb=83952450439”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@add-diversion-header:3] Set(“PJSIP/si3000-00000595”, “origphone=839522XXXXX”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@add-diversion-header:4] Set(“PJSIP/si3000-00000595”, “counter=1”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@add-diversion-header:5] Set(“PJSIP/si3000-00000595”, “counter=1”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@add-diversion-header:6] Set(“PJSIP/si3000-00000595”, “PJSIP_HEADER(add,Diversion)=“83952450439” tel:83952450439;reason=unconditional;privacy=off;screen=no;counter=1”)
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@add-diversion-header:7] GotoIf(“PJSIP/si3000-00000595”, “0?return”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@add-diversion-header:8] Set(“PJSIP/si3000-00000595”, “PJSIP_HEADER(add,Diversion)=“839522XXXXX” tel:839522XXXXX;reason=unconditional;privacy=off;screen=no;counter=1”)
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] pbx.c: Executing [s@add-diversion-header:9] Return(“PJSIP/si3000-00000595”, “”) in new stack
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] app_stack.c: Spawn extension (from-pjsip, s, 1) exited non-zero on ‘PJSIP/si3000-00000595’
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] app_stack.c: PJSIP/si3000-00000595 Internal Gosub(add-diversion-header,s,1(83952450439,839522XXXXX)) complete GOSUB_RETVAL=
[2019-06-24 19:28:55] VERBOSE[8988][C-000002ec] app_dial.c: Called PJSIP/839522XXXXX@si3000
[2019-06-24 19:28:55] VERBOSE[23201] netsock2.c: Using SIP RTP Audio TOS bits 184
[2019-06-24 19:28:55] VERBOSE[23201] netsock2.c: Using SIP RTP Audio CoS mark 5
[2019-06-24 19:28:56] VERBOSE[8988][C-000002ec] app_dial.c: PJSIP/si3000-00000595 is ringing
[2019-06-24 19:28:56] VERBOSE[8986][C-000002ec] app_dial.c: Local/s@call-client-phones-00000191;1 is ringing
[2019-06-24 19:28:56] VERBOSE[8988][C-000002ec] app_dial.c: PJSIP/si3000-00000595 is ringing
[2019-06-24 19:28:58] VERBOSE[8988][C-000002ec] app_dial.c: PJSIP/si3000-00000595 answered Local/s@call-client-phones-00000191;2
[2019-06-24 19:28:58] VERBOSE[8986][C-000002ec] app_dial.c: Local/s@call-client-phones-00000191;1 answered PJSIP/si3000-00000594
[2019-06-24 19:28:58] VERBOSE[8986][C-000002ec] res_musiconhold.c: Stopped music on hold on PJSIP/si3000-00000594
[2019-06-24 19:28:58] VERBOSE[8989][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000595 joined ‘simple_bridge’ basic-bridge
[2019-06-24 19:28:58] VERBOSE[8990][C-000002ec] bridge_channel.c: Channel Local/s@call-client-phones-00000191;1 joined ‘simple_bridge’ basic-bridge <6520bed9-7b2c-4ffe-9d13-a707ba1c706f>
[2019-06-24 19:28:58] VERBOSE[8988][C-000002ec] bridge_channel.c: Channel Local/s@call-client-phones-00000191;2 joined ‘simple_bridge’ basic-bridge
[2019-06-24 19:28:58] VERBOSE[8986][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000594 joined ‘simple_bridge’ basic-bridge <6520bed9-7b2c-4ffe-9d13-a707ba1c706f>
[2019-06-24 19:28:58] WARNING[8988][C-000002ec] channel.c: Exceptionally long voice queue length queuing to Local/s@call-client-phones-00000191;1
[2019-06-24 19:28:58] VERBOSE[8990][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000594 left ‘simple_bridge’ basic-bridge <6520bed9-7b2c-4ffe-9d13-a707ba1c706f>
[2019-06-24 19:28:58] VERBOSE[8990][C-000002ec] bridge_channel.c: Channel Local/s@call-client-phones-00000191;2 left ‘simple_bridge’ basic-bridge
[2019-06-24 19:28:58] VERBOSE[8990][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000594 swapped with Local/s@call-client-phones-00000191;2 into ‘simple_bridge’ basic-bridge
[2019-06-24 19:28:58] VERBOSE[8990][C-000002ec] bridge_channel.c: Channel Local/s@call-client-phones-00000191;1 left ‘simple_bridge’ basic-bridge <6520bed9-7b2c-4ffe-9d13-a707ba1c706f>
[2019-06-24 19:28:58] VERBOSE[8988][C-000002ec] pbx.c: Spawn extension (call-client-phones, s, 7) exited non-zero on ‘Local/s@call-client-phones-00000191;2’
[2019-06-24 19:29:11] VERBOSE[8986][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000594 left ‘simple_bridge’ basic-bridge
[2019-06-24 19:29:11] VERBOSE[8989][C-000002ec] bridge_channel.c: Channel PJSIP/si3000-00000595 left ‘simple_bridge’ basic-bridge
[2019-06-24 19:29:11] VERBOSE[8986][C-000002ec] pbx.c: Spawn extension (call-client, s, 29) exited non-zero on ‘PJSIP/si3000-00000594’
[2019-06-24 19:29:11] VERBOSE[8987][C-000002ec] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2019-06-24 19:29:11] VERBOSE[8987][C-000002ec] app_mixmonitor.c: End MixMonitor Recording PJSIP/si3000-00000594

7

Nothing immediately stands out as being the cause. If you add a “/n” to the end of your Local dial target does that make it go away?

8

No, it does not help. I have tried the “/n” option.

9

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