SRTP Problem? -

steve_pbuk · July 19, 2018, 4:42pm

Today I have enabled SIP TLS and SRTP on about 10 Sangoma S500 phones. (Latest firmware installed)

During testing I noticed the following in the logs:

[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] app_dial.c: PJSIP/2194-00000008 is ringing
[2018-07-19 17:34:07] VERBOSE[9480][C-00000005] app_dial.c: PJSIP/2194-00000008 answered PJSIP/2197-00000007
[2018-07-19 17:34:07] VERBOSE[9578][C-00000005] bridge_channel.c: Channel PJSIP/2194-00000008 joined 'simple_bridge' basic-bridge <9a8b1cef-85e8-4a28-a586-f5d048ec0166>
[2018-07-19 17:34:07] VERBOSE[9480][C-00000005] bridge_channel.c: Channel PJSIP/2197-00000007 joined 'simple_bridge' basic-bridge <9a8b1cef-85e8-4a28-a586-f5d048ec0166>
[2018-07-19 17:34:17] VERBOSE[9578][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
[2018-07-19 17:34:17] VERBOSE[9480][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
[2018-07-19 17:34:22] VERBOSE[9578][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
[2018-07-19 17:34:22] VERBOSE[9480][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
[2018-07-19 17:34:27] VERBOSE[9578][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
[2018-07-19 17:34:27] VERBOSE[9480][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
[2018-07-19 17:34:32] VERBOSE[9578][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
[2018-07-19 17:34:32] VERBOSE[9480][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation

Just wondering if this is anything I need to worry about and fix?? The call seems to work OK and I had two way audio.

I will paste the full log below incase it is of any use:

[2018-07-19 17:34:01] VERBOSE[8369] pbx_variables.c: Setting global variable 'SIPDOMAIN' to 'pbx-01.cspencerltd.co.uk'
[2018-07-19 17:34:01] VERBOSE[8369] netsock2.c: Using SIP RTP Audio TOS bits 184
[2018-07-19 17:34:01] VERBOSE[8369] netsock2.c: Using SIP RTP Audio CoS mark 5
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [2194@from-internal:1] GotoIf("PJSIP/2197-00000007", "1?ext-local,2194,1:followme-check,2194,1") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (ext-local,2194,1)
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [2194@ext-local:1] Set("PJSIP/2197-00000007", "__RINGTIMER=15") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [2194@ext-local:2] Macro("PJSIP/2197-00000007", "exten-vm,2194,2194,0,0,0") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:1] Macro("PJSIP/2197-00000007", "user-callerid,") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/2197-00000007", "TOUCH_MONITOR=1532018041.11") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/2197-00000007", "AMPUSER=2197") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("PJSIP/2197-00000007", "0?report") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("PJSIP/2197-00000007", "1?Set(REALCALLERIDNUM=2197)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/2197-00000007", "AMPUSER=2197") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("PJSIP/2197-00000007", "0?limit") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/2197-00000007", "AMPUSERCIDNAME=Steve Allen") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("PJSIP/2197-00000007", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("PJSIP/2197-00000007", "0?report") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/2197-00000007", "AMPUSERCID=2197") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:11] Set("PJSIP/2197-00000007", "__DIAL_OPTIONS=HhTtr") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:12] Set("PJSIP/2197-00000007", "CALLERID(all)="Steve Allen" <2197>") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("PJSIP/2197-00000007", "0?limit") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("PJSIP/2197-00000007", "0?Set(GROUP(concurrency_limit)=2197)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("PJSIP/2197-00000007", "0?Set(CHANNEL(language)=)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:16] NoOp("PJSIP/2197-00000007", "Macro Depth is 2") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("PJSIP/2197-00000007", "1?report2:macroerror") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("PJSIP/2197-00000007", "0?continue") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:19] ExecIf("PJSIP/2197-00000007", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:20] Set("PJSIP/2197-00000007", "__TTL=64") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:21] GotoIf("PJSIP/2197-00000007", "1?continue") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:37] Set("PJSIP/2197-00000007", "CALLERID(number)=2197") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:38] Set("PJSIP/2197-00000007", "CALLERID(name)=Steve Allen") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("PJSIP/2197-00000007", "0?cnum") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:40] Set("PJSIP/2197-00000007", "CDR(cnam)=Steve Allen") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:41] Set("PJSIP/2197-00000007", "CDR(cnum)=2197") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-user-callerid:42] Set("PJSIP/2197-00000007", "CHANNEL(language)=en_GB") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:2] Set("PJSIP/2197-00000007", "RingGroupMethod=none") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:3] Set("PJSIP/2197-00000007", "__EXTTOCALL=2194") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:4] Set("PJSIP/2197-00000007", "__PICKUPMARK=2194") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:5] Set("PJSIP/2197-00000007", "RT=15") in new stack
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:6] ExecIf("PJSIP/2197-00000007", "0?Macro(vm,2194,DIRECTDIAL,)") in new stack
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:7] ExecIf("PJSIP/2197-00000007", "0?MacroExit()") in new stack
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:8] ExecIf("PJSIP/2197-00000007", "0?Gosub(ext-intercom,*802194,1())") in new stack
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:9] ExecIf("PJSIP/2197-00000007", "0?MacroExit()") in new stack
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:10] ExecIf("PJSIP/2197-00000007", "0?ChanSpy(PJSIP/2194,q)") in new stack
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:11] ExecIf("PJSIP/2197-00000007", "0?MacroExit()") in new stack
[2018-07-19 17:34:01] ERROR[9480][C-00000005] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:12] ExecIf("PJSIP/2197-00000007", "0?Macro(vm,2194,DIRECTDIAL,)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:13] ExecIf("PJSIP/2197-00000007", "0?MacroExit()") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:14] ExecIf("PJSIP/2197-00000007", "0?Gosub(ext-intercom,*802194,1())") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:15] ExecIf("PJSIP/2197-00000007", "0?MacroExit()") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:16] ExecIf("PJSIP/2197-00000007", "0?ChanSpy(PJSIP/2194,q)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:17] ExecIf("PJSIP/2197-00000007", "0?MacroExit()") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:18] Gosub("PJSIP/2197-00000007", "sub-record-check,s,1(exten,2194,dontcare)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/2197-00000007", "0?initialized") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/2197-00000007", "__REC_STATUS=INITIALIZED") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/2197-00000007", "NOW=1532018041") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/2197-00000007", "__DAY=19") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/2197-00000007", "__MONTH=07") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/2197-00000007", "__YEAR=2018") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/2197-00000007", "__TIMESTR=20180719-173401") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/2197-00000007", "__FROMEXTEN=2197") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/2197-00000007", "__MON_FMT=wav") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/2197-00000007", "Recordings initialized") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/2197-00000007", "0?Set(ARG3=dontcare)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/2197-00000007", "REC_POLICY_MODE_SAVE=") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/2197-00000007", "0?Set(REC_STATUS=NO)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/2197-00000007", "5?checkaction") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/2197-00000007", "1?sub-record-check,exten,1") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:1] NoOp("PJSIP/2197-00000007", "Exten Recording Check between 2197 and 2194") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:2] Set("PJSIP/2197-00000007", "CALLTYPE=internal") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:3] ExecIf("PJSIP/2197-00000007", "0?Set(CALLTYPE=)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:4] Set("PJSIP/2197-00000007", "CALLEE=dontcare") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:5] ExecIf("PJSIP/2197-00000007", "0?Set(CALLEE=dontcare)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:6] GotoIf("PJSIP/2197-00000007", "0?callee") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:7] GotoIf("PJSIP/2197-00000007", "1?caller") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (sub-record-check,exten,13)
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:13] Set("PJSIP/2197-00000007", "RECMODE=dontcare") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:14] ExecIf("PJSIP/2197-00000007", "0?Set(RECMODE=dontcare)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:15] ExecIf("PJSIP/2197-00000007", "1?Set(RECMODE=dontcare)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:16] Gosub("PJSIP/2197-00000007", "recordcheck,1(dontcare,internal,2194)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/2197-00000007", "Starting recording check against dontcare") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/2197-00000007", "dontcare") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/2197-00000007", "") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [exten@sub-record-check:17] Return("PJSIP/2197-00000007", "") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:19] GotoIf("PJSIP/2197-00000007", "1?macrodial") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (macro-exten-vm,s,25)
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:25] GosubIf("PJSIP/2197-00000007", "0?clrheader,1()") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-exten-vm:26] Macro("PJSIP/2197-00000007", "dial-one,15,HhTtr,2194") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:1] Set("PJSIP/2197-00000007", "DEXTEN=2194") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:2] UserEvent("PJSIP/2197-00000007", "zulu-inbound-call,type:macro-dial-one,from:2197,to:2194") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:3] ExecIf("PJSIP/2197-00000007", "0?Set(__EXTTOCALL=2194)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:4] Set("PJSIP/2197-00000007", "DIALSTATUS_CW=") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:5] GosubIf("PJSIP/2197-00000007", "0?screen,1()") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:6] GosubIf("PJSIP/2197-00000007", "0?cf,1()") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:7] GotoIf("PJSIP/2197-00000007", "1?skip1") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (macro-dial-one,s,10)
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:10] GotoIf("PJSIP/2197-00000007", "0?nodial") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:11] GotoIf("PJSIP/2197-00000007", "0?continue") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:12] Set("PJSIP/2197-00000007", "EXTHASCW=ENABLED") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:13] GotoIf("PJSIP/2197-00000007", "0?next1:cwinusebusy") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (macro-dial-one,s,25)
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:25] GotoIf("PJSIP/2197-00000007", "0?next3:continue") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (macro-dial-one,s,27)
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:27] GotoIf("PJSIP/2197-00000007", "0?nodial") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:28] GosubIf("PJSIP/2197-00000007", "1?dstring,1():dlocal,1()") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:1] Set("PJSIP/2197-00000007", "DSTRING=") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:2] Set("PJSIP/2197-00000007", "DEVICES=2194") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf("PJSIP/2197-00000007", "0?Return()") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf("PJSIP/2197-00000007", "0?Set(DEVICES=194)") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:5] Set("PJSIP/2197-00000007", "LOOPCNT=1") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:6] Set("PJSIP/2197-00000007", "ITER=1") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:7] Set("PJSIP/2197-00000007", "THISDIAL=PJSIP/2194") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf("PJSIP/2197-00000007", "1?zap2dahdi,1()") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf("PJSIP/2197-00000007", "0?Return()") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set("PJSIP/2197-00000007", "NEWDIAL=") in new stack
[2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [zap2dahdi@macro-dial-one:3]

Looks like I need to split the paste over two posts. Rest of the log is below.

Forgot to mention, the server is up to date with system updates and module updates.

steve_pbuk · July 19, 2018, 4:42pm

2nd part of the log:

Set("PJSIP/2197-00000007", "LOOPCNT2=1") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set("PJSIP/2197-00000007", "ITER2=1") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set("PJSIP/2197-00000007", "THISPART2=PJSIP/2194") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf("PJSIP/2197-00000007", "0?Set(THISPART2=DAHDIIP/2194)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set("PJSIP/2197-00000007", "NEWDIAL=PJSIP/2194&") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set("PJSIP/2197-00000007", "ITER2=2") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf("PJSIP/2197-00000007", "0?begin2") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set("PJSIP/2197-00000007", "THISDIAL=PJSIP/2194") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return("PJSIP/2197-00000007", "") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf("PJSIP/2197-00000007", "0?docheck") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:10] NoOp("PJSIP/2197-00000007", "Debug: Found PJSIP Destination PJSIP/2194") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:11] GotoIf("PJSIP/2197-00000007", "0?doset") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:12] NoOp("PJSIP/2197-00000007", "Debug: Updating PJSIP Destination with PJSIP_DIAL_CONTACTS") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:13] Set("PJSIP/2197-00000007", "THISDIAL=PJSIP/2194/sip:[email protected]:5060;transport=TLS") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:14] ExecIf("PJSIP/2197-00000007", "0?Set(DIALSTATUS=CHANUNAVAIL)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:15] GotoIf("PJSIP/2197-00000007", "0?skipset") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:16] Set("PJSIP/2197-00000007", "DSTRING=PJSIP/2194/sip:[email protected]:5060;transport=TLS&") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:17] Set("PJSIP/2197-00000007", "ITER=2") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:18] GotoIf("PJSIP/2197-00000007", "0?begin") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:19] ExecIf("PJSIP/2197-00000007", "0?Return()") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:20] Set("PJSIP/2197-00000007", "DSTRING=PJSIP/2194/sip:[email protected]:5060;transport=TLS") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [dstring@macro-dial-one:21] Return("PJSIP/2197-00000007", "") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:29] GotoIf("PJSIP/2197-00000007", "0?nodial") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:30] GotoIf("PJSIP/2197-00000007", "0?skiptrace") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:31] GosubIf("PJSIP/2197-00000007", "1?ctset,1():ctclear,1()") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [ctset@macro-dial-one:1] Set("PJSIP/2197-00000007", "DB(CALLTRACE/2194)=2197") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [ctset@macro-dial-one:2] Return("PJSIP/2197-00000007", "") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:32] Set("PJSIP/2197-00000007", "D_OPTIONS=HhTtr") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:33] GosubIf("PJSIP/2197-00000007", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:34] NoOp("PJSIP/2197-00000007", "Blind Transfer: , Attended Transfer: , User: 2197, Alert Info: ") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:35] ExecIf("PJSIP/2197-00000007", "1?Set(ALERT_INFO=)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:36] ExecIf("PJSIP/2197-00000007", "0?Set(ALERT_INFO=)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:37] ExecIf("PJSIP/2197-00000007", "0?Set(ALERT_INFO=)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:38] ExecIf("PJSIP/2197-00000007", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:39] ExecIf("PJSIP/2197-00000007", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:40] GosubIf("PJSIP/2197-00000007", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:41] ExecIf("PJSIP/2197-00000007", "0?Set(CHANNEL(musicclass)=)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:42] GosubIf("PJSIP/2197-00000007", "0?qwait,1()") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:43] Set("PJSIP/2197-00000007", "__CWIGNORE=") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:44] Set("PJSIP/2197-00000007", "__KEEPCID=TRUE") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:45] GotoIf("PJSIP/2197-00000007", "0?usegoto,1") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:46] GotoIf("PJSIP/2197-00000007", "0?godial") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:47] Gosub("PJSIP/2197-00000007", "sub-presencestate-display,s,1(2194)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@sub-presencestate-display:1] Goto("PJSIP/2197-00000007", "state-not_set,1") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (sub-presencestate-display,state-not_set,1)
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [state-not_set@sub-presencestate-display:1] Set("PJSIP/2197-00000007", "PRESENCESTATE_DISPLAY=") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [state-not_set@sub-presencestate-display:2] Return("PJSIP/2197-00000007", "") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:48] Set("PJSIP/2197-00000007", "CONNECTEDLINE(name,i)=David Turtill") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:49] Set("PJSIP/2197-00000007", "CONNECTEDLINE(num)=2194") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:50] Set("PJSIP/2197-00000007", "D_OPTIONS=HhTtrI") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:51] Macro("PJSIP/2197-00000007", "dialout-one-predial-hook,") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit("PJSIP/2197-00000007", "") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:52] ExecIf("PJSIP/2197-00000007", "0?Set(D_OPTIONS=HhtrII)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:53] GotoIf("PJSIP/2197-00000007", "1?zulunourl") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (macro-dial-one,s,55)
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:55] ExecIf("PJSIP/2197-00000007", "0?Set(ZULU_TYPE=)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:56] GotoIf("PJSIP/2197-00000007", "1?skippopup") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (macro-dial-one,s,59)
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:59] UserEvent("PJSIP/2197-00000007", "zulu-call,eventtype:calling,extension:2194,type:,url:,cnam:Steve Allen,cnum:2197,lid:1532018041.11,from:2197,to:2194,user:") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:60] NoOp("PJSIP/2197-00000007", "Zulu Finished") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:61] Set("PJSIP/2197-00000007", "_zuludialopts=") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:62] AGI("PJSIP/2197-00000007", "zulureplace-one.agi,DSTRING,90") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/zulureplace-one.agi
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] res_agi.c: zulureplace-one.agi,DSTRING,90: DIALSTRING: PJSIP/2194/sip:[email protected]:5060;transport=TLS
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] res_agi.c: zulureplace-one.agi,DSTRING,90: DIALOPTS: HhTtrI
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] res_agi.c: zulureplace-one.agi,DSTRING,90: TIMEOUT: 15
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] res_agi.c: zulureplace-one.agi,DSTRING,90: NEWDIALSTRING: PJSIP/2194/sip:[email protected]:5060;transport=TLS
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] res_agi.c: <PJSIP/2197-00000007>AGI Script zulureplace-one.agi completed, returning 0
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:63] NoOp("PJSIP/2197-00000007", "") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:64] ExecIf("PJSIP/2197-00000007", "0?Set(D_OPTIONS=HhTtrIg)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-dial-one:65] Dial("PJSIP/2197-00000007", "PJSIP/2194/sip:[email protected]:5060;transport=TLS,15,HhTtrIb(func-apply-sipheaders^s^1)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] app_stack.c: PJSIP/2194-00000008 Internal Gosub(func-apply-sipheaders,s,1) start
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@func-apply-sipheaders:1] UserEvent("PJSIP/2194-00000008", "zulu-call-b,type:func-apply-sipheaders,to:2194,from:2197") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("PJSIP/2194-00000008", "Applying SIP Headers to channel") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/2194-00000008", "SIPHEADERKEYS=") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@func-apply-sipheaders:4] ExecIf("PJSIP/2194-00000008", "0?Set(Rheader=1)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/2194-00000008", "0") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] app_while.c: Jumping to priority 8
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("PJSIP/2194-00000008", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] pbx.c: Executing [s@func-apply-sipheaders:10] Return("PJSIP/2194-00000008", "") in new stack
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] app_stack.c: Spawn extension (from-internal, 2194, 1) exited non-zero on 'PJSIP/2194-00000008'
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] app_stack.c: PJSIP/2194-00000008 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] app_dial.c: Called PJSIP/2194/sip:[email protected]:5060;transport=TLS
        [2018-07-19 17:34:01] VERBOSE[8370] netsock2.c: Using SIP RTP Audio TOS bits 184
        [2018-07-19 17:34:01] VERBOSE[8370] netsock2.c: Using SIP RTP Audio CoS mark 5
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] app_dial.c: Connected line update to PJSIP/2197-00000007 prevented.
        [2018-07-19 17:34:01] VERBOSE[9480][C-00000005] app_dial.c: PJSIP/2194-00000008 is ringing
        [2018-07-19 17:34:07] VERBOSE[9480][C-00000005] app_dial.c: PJSIP/2194-00000008 answered PJSIP/2197-00000007
        [2018-07-19 17:34:07] VERBOSE[9578][C-00000005] bridge_channel.c: Channel PJSIP/2194-00000008 joined 'simple_bridge' basic-bridge <9a8b1cef-85e8-4a28-a586-f5d048ec0166>
        [2018-07-19 17:34:07] VERBOSE[9480][C-00000005] bridge_channel.c: Channel PJSIP/2197-00000007 joined 'simple_bridge' basic-bridge <9a8b1cef-85e8-4a28-a586-f5d048ec0166>
        [2018-07-19 17:34:17] VERBOSE[9578][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
        [2018-07-19 17:34:17] VERBOSE[9480][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
        [2018-07-19 17:34:22] VERBOSE[9578][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
        [2018-07-19 17:34:22] VERBOSE[9480][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
        [2018-07-19 17:34:27] VERBOSE[9578][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
        [2018-07-19 17:34:27] VERBOSE[9480][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
        [2018-07-19 17:34:32] VERBOSE[9578][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
        [2018-07-19 17:34:32] VERBOSE[9480][C-00000005] res_srtp.c: SRTCP unprotect failed because of unable to perform desired validation
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] bridge_channel.c: Channel PJSIP/2197-00000007 left 'simple_bridge' basic-bridge <9a8b1cef-85e8-4a28-a586-f5d048ec0166>
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] app_macro.c: Spawn extension (macro-dial-one, s, 65) exited non-zero on 'PJSIP/2197-00000007' in macro 'dial-one'
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] app_macro.c: Spawn extension (macro-exten-vm, s, 26) exited non-zero on 'PJSIP/2197-00000007' in macro 'exten-vm'
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] pbx.c: Spawn extension (ext-local, 2194, 2) exited non-zero on 'PJSIP/2197-00000007'
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] pbx.c: Executing [h@ext-local:1] Macro("PJSIP/2197-00000007", "hangupcall,") in new stack
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/2197-00000007", "1?theend") in new stack
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] pbx_builtins.c: Goto (macro-hangupcall,s,3)
        [2018-07-19 17:34:35] VERBOSE[9578][C-00000005] bridge_channel.c: Channel PJSIP/2194-00000008 left 'simple_bridge' basic-bridge <9a8b1cef-85e8-4a28-a586-f5d048ec0166>
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/2197-00000007", "0?Set(CDR(recordingfile)=)") in new stack
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-hangupcall:4] NoOp("PJSIP/2197-00000007", "PJSIP/2194-00000008 monior file= ") in new stack
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-hangupcall:5] AGI("PJSIP/2197-00000007", "attendedtransfer-rec-restart.php,PJSIP/2194-00000008,") in new stack
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] res_agi.c: <PJSIP/2197-00000007>AGI Script attendedtransfer-rec-restart.php completed, returning 0
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] pbx.c: Executing [s@macro-hangupcall:6] Hangup("PJSIP/2197-00000007", "") in new stack
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on 'PJSIP/2197-00000007' in macro 'hangupcall'
        [2018-07-19 17:34:35] VERBOSE[9480][C-00000005] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/2197-00000007'

steve_pbuk · July 23, 2018, 8:15am

I am having intermittent problems this morning. 2 of the phones that I have enabled SIP TLS and SRTP on are now having one way audio problems. They can hear the other caller but the caller can not hear them.

If I reboot the phones calls work fine. Here are the logs after the phone has been rebooted:

I’ve had to split the log output over two posts because of character limits:

Log Part 1

[2018-07-23 08:57:54] VERBOSE[3701] pbx_variables.c: Setting global variable 'SIPDOMAIN' to 'pbx-01.cspencerltd.co.uk'
[2018-07-23 08:57:54] VERBOSE[3701] netsock2.c: Using SIP RTP Audio TOS bits 184
[2018-07-23 08:57:54] VERBOSE[3701] netsock2.c: Using SIP RTP Audio CoS mark 5
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [2197@from-internal:1] GotoIf("PJSIP/2190-000002a9", "1?ext-local,2197,1:followme-check,2197,1") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (ext-local,2197,1)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [2197@ext-local:1] Set("PJSIP/2190-000002a9", "__RINGTIMER=15") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [2197@ext-local:2] Macro("PJSIP/2190-000002a9", "exten-vm,2197,2197,0,0,0") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:1] Macro("PJSIP/2190-000002a9", "user-callerid,") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/2190-000002a9", "TOUCH_MONITOR=1532332674.1767") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/2190-000002a9", "AMPUSER=2190") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("PJSIP/2190-000002a9", "0?report") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("PJSIP/2190-000002a9", "1?Set(REALCALLERIDNUM=2190)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/2190-000002a9", "AMPUSER=2190") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("PJSIP/2190-000002a9", "0?limit") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/2190-000002a9", "AMPUSERCIDNAME=Simon Wood") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("PJSIP/2190-000002a9", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("PJSIP/2190-000002a9", "0?report") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/2190-000002a9", "AMPUSERCID=2190") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:11] Set("PJSIP/2190-000002a9", "__DIAL_OPTIONS=HhTtr") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:12] Set("PJSIP/2190-000002a9", "CALLERID(all)="Simon Wood" <2190>") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("PJSIP/2190-000002a9", "0?limit") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("PJSIP/2190-000002a9", "0?Set(GROUP(concurrency_limit)=2190)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("PJSIP/2190-000002a9", "0?Set(CHANNEL(language)=)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:16] NoOp("PJSIP/2190-000002a9", "Macro Depth is 2") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("PJSIP/2190-000002a9", "1?report2:macroerror") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("PJSIP/2190-000002a9", "0?continue") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:19] ExecIf("PJSIP/2190-000002a9", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:20] Set("PJSIP/2190-000002a9", "__TTL=64") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:21] GotoIf("PJSIP/2190-000002a9", "1?continue") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:37] Set("PJSIP/2190-000002a9", "CALLERID(number)=2190") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:38] Set("PJSIP/2190-000002a9", "CALLERID(name)=Simon Wood") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("PJSIP/2190-000002a9", "0?cnum") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:40] Set("PJSIP/2190-000002a9", "CDR(cnam)=Simon Wood") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:41] Set("PJSIP/2190-000002a9", "CDR(cnum)=2190") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-user-callerid:42] Set("PJSIP/2190-000002a9", "CHANNEL(language)=en_GB") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:2] Set("PJSIP/2190-000002a9", "RingGroupMethod=none") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:3] Set("PJSIP/2190-000002a9", "__EXTTOCALL=2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:4] Set("PJSIP/2190-000002a9", "__PICKUPMARK=2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:5] Set("PJSIP/2190-000002a9", "RT=15") in new stack
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:6] ExecIf("PJSIP/2190-000002a9", "0?Macro(vm,2197,DIRECTDIAL,)") in new stack
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:7] ExecIf("PJSIP/2190-000002a9", "0?MacroExit()") in new stack
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:8] ExecIf("PJSIP/2190-000002a9", "0?Gosub(ext-intercom,*802197,1())") in new stack
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:9] ExecIf("PJSIP/2190-000002a9", "0?MacroExit()") in new stack
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:10] ExecIf("PJSIP/2190-000002a9", "0?ChanSpy(PJSIP/2197,q)") in new stack
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:11] ExecIf("PJSIP/2190-000002a9", "0?MacroExit()") in new stack
[2018-07-23 08:57:54] ERROR[14724][C-00000141] pbx_functions.c: Function SIP_HEADER not registered
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:12] ExecIf("PJSIP/2190-000002a9", "0?Macro(vm,2197,DIRECTDIAL,)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:13] ExecIf("PJSIP/2190-000002a9", "0?MacroExit()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:14] ExecIf("PJSIP/2190-000002a9", "0?Gosub(ext-intercom,*802197,1())") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:15] ExecIf("PJSIP/2190-000002a9", "0?MacroExit()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:16] ExecIf("PJSIP/2190-000002a9", "0?ChanSpy(PJSIP/2197,q)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:17] ExecIf("PJSIP/2190-000002a9", "0?MacroExit()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:18] Gosub("PJSIP/2190-000002a9", "sub-record-check,s,1(exten,2197,dontcare)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/2190-000002a9", "0?initialized") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/2190-000002a9", "__REC_STATUS=INITIALIZED") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/2190-000002a9", "NOW=1532332674") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/2190-000002a9", "__DAY=23") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/2190-000002a9", "__MONTH=07") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/2190-000002a9", "__YEAR=2018") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/2190-000002a9", "__TIMESTR=20180723-085754") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/2190-000002a9", "__FROMEXTEN=2190") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/2190-000002a9", "__MON_FMT=wav") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/2190-000002a9", "Recordings initialized") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/2190-000002a9", "0?Set(ARG3=dontcare)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/2190-000002a9", "REC_POLICY_MODE_SAVE=") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/2190-000002a9", "0?Set(REC_STATUS=NO)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/2190-000002a9", "5?checkaction") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/2190-000002a9", "1?sub-record-check,exten,1") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:1] NoOp("PJSIP/2190-000002a9", "Exten Recording Check between 2190 and 2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:2] Set("PJSIP/2190-000002a9", "CALLTYPE=internal") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:3] ExecIf("PJSIP/2190-000002a9", "0?Set(CALLTYPE=)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:4] Set("PJSIP/2190-000002a9", "CALLEE=dontcare") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:5] ExecIf("PJSIP/2190-000002a9", "0?Set(CALLEE=dontcare)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:6] GotoIf("PJSIP/2190-000002a9", "0?callee") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:7] GotoIf("PJSIP/2190-000002a9", "1?caller") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (sub-record-check,exten,13)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:13] Set("PJSIP/2190-000002a9", "RECMODE=dontcare") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:14] ExecIf("PJSIP/2190-000002a9", "0?Set(RECMODE=dontcare)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:15] ExecIf("PJSIP/2190-000002a9", "1?Set(RECMODE=dontcare)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:16] Gosub("PJSIP/2190-000002a9", "recordcheck,1(dontcare,internal,2197)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/2190-000002a9", "Starting recording check against dontcare") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/2190-000002a9", "dontcare") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/2190-000002a9", "") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [exten@sub-record-check:17] Return("PJSIP/2190-000002a9", "") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:19] GotoIf("PJSIP/2190-000002a9", "1?macrodial") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (macro-exten-vm,s,25)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:25] GosubIf("PJSIP/2190-000002a9", "0?clrheader,1()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-exten-vm:26] Macro("PJSIP/2190-000002a9", "dial-one,15,HhTtr,2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:1] Set("PJSIP/2190-000002a9", "DEXTEN=2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:2] UserEvent("PJSIP/2190-000002a9", "zulu-inbound-call,type:macro-dial-one,from:2190,to:2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:3] ExecIf("PJSIP/2190-000002a9", "0?Set(__EXTTOCALL=2197)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:4] Set("PJSIP/2190-000002a9", "DIALSTATUS_CW=") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:5] GosubIf("PJSIP/2190-000002a9", "0?screen,1()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:6] GosubIf("PJSIP/2190-000002a9", "0?cf,1()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:7] GotoIf("PJSIP/2190-000002a9", "1?skip1") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (macro-dial-one,s,10)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:10] GotoIf("PJSIP/2190-000002a9", "0?nodial") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:11] GotoIf("PJSIP/2190-000002a9", "0?continue") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:12] Set("PJSIP/2190-000002a9", "EXTHASCW=ENABLED") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:13] GotoIf("PJSIP/2190-000002a9", "0?next1:cwinusebusy") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (macro-dial-one,s,25)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:25] GotoIf("PJSIP/2190-000002a9", "0?next3:continue") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (macro-dial-one,s,27)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:27] GotoIf("PJSIP/2190-000002a9", "0?nodial") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:28] GosubIf("PJSIP/2190-000002a9", "1?dstring,1():dlocal,1()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:1] Set("PJSIP/2190-000002a9", "DSTRING=") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:2] Set("PJSIP/2190-000002a9", "DEVICES=992197&2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf("PJSIP/2190-000002a9", "0?Return()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf("PJSIP/2190-000002a9", "0?Set(DEVICES=92197&2197)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:5] Set("PJSIP/2190-000002a9", "LOOPCNT=2") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:6] Set("PJSIP/2190-000002a9", "ITER=1") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:7] Set("PJSIP/2190-000002a9", "THISDIAL=PJSIP/992197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf("PJSIP/2190-000002a9", "1?zap2dahdi,1()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf("PJSIP/2190-000002a9", "0?Return()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set("PJSIP/2190-000002a9", "NEWDIAL=") in new stack

steve_pbuk · July 23, 2018, 8:15am

Log Part 2

[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set("PJSIP/2190-000002a9", "LOOPCNT2=1") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set("PJSIP/2190-000002a9", "ITER2=1") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set("PJSIP/2190-000002a9", "THISPART2=PJSIP/992197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf("PJSIP/2190-000002a9", "0?Set(THISPART2=DAHDIIP/992197)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set("PJSIP/2190-000002a9", "NEWDIAL=PJSIP/992197&") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set("PJSIP/2190-000002a9", "ITER2=2") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf("PJSIP/2190-000002a9", "0?begin2") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set("PJSIP/2190-000002a9", "THISDIAL=PJSIP/992197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return("PJSIP/2190-000002a9", "") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf("PJSIP/2190-000002a9", "0?docheck") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:10] NoOp("PJSIP/2190-000002a9", "Debug: Found PJSIP Destination PJSIP/992197") in new
stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:11] GotoIf("PJSIP/2190-000002a9", "0?doset") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:12] NoOp("PJSIP/2190-000002a9", "Debug: Updating PJSIP Destination with PJSIP_DIAL_CONTACTS") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:13] Set("PJSIP/2190-000002a9", "THISDIAL=") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:14] ExecIf("PJSIP/2190-000002a9", "1?Set(DIALSTATUS=CHANUNAVAIL)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:15] GotoIf("PJSIP/2190-000002a9", "1?skipset") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (macro-dial-one,dstring,17)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:17] Set("PJSIP/2190-000002a9", "ITER=2") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:18] GotoIf("PJSIP/2190-000002a9", "1?begin") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (macro-dial-one,dstring,7)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:7] Set("PJSIP/2190-000002a9", "THISDIAL=PJSIP/2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf("PJSIP/2190-000002a9", "1?zap2dahdi,1()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf("PJSIP/2190-000002a9", "0?Return()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set("PJSIP/2190-000002a9", "NEWDIAL=") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set("PJSIP/2190-000002a9", "LOOPCNT2=1") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set("PJSIP/2190-000002a9", "ITER2=1") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set("PJSIP/2190-000002a9", "THISPART2=PJSIP/2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf("PJSIP/2190-000002a9", "0?Set(THISPART2=DAHDIIP/2197)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set("PJSIP/2190-000002a9", "NEWDIAL=PJSIP/2197&") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set("PJSIP/2190-000002a9", "ITER2=2") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf("PJSIP/2190-000002a9", "0?begin2") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set("PJSIP/2190-000002a9", "THISDIAL=PJSIP/2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return("PJSIP/2190-000002a9", "") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf("PJSIP/2190-000002a9", "0?docheck") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:10] NoOp("PJSIP/2190-000002a9", "Debug: Found PJSIP Destination PJSIP/2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:11] GotoIf("PJSIP/2190-000002a9", "0?doset") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:12] NoOp("PJSIP/2190-000002a9", "Debug: Updating PJSIP Destination with PJSIP_DIAL_CONTACTS") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:13] Set("PJSIP/2190-000002a9", "THISDIAL=PJSIP/2197/sip:[email protected]:5060;transport=TLS") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:14] ExecIf("PJSIP/2190-000002a9", "0?Set(DIALSTATUS=CHANUNAVAIL)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:15] GotoIf("PJSIP/2190-000002a9", "0?skipset") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:16] Set("PJSIP/2190-000002a9", "DSTRING=PJSIP/2197/sip:[email protected]:5060;transport=TLS&") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:17] Set("PJSIP/2190-000002a9", "ITER=3") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:18] GotoIf("PJSIP/2190-000002a9", "0?begin") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:19] ExecIf("PJSIP/2190-000002a9", "0?Return()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:20] Set("PJSIP/2190-000002a9", "DSTRING=PJSIP/2197/sip:[email protected]:5060;transport=TLS") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [dstring@macro-dial-one:21] Return("PJSIP/2190-000002a9", "") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:29] GotoIf("PJSIP/2190-000002a9", "0?nodial") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:30] GotoIf("PJSIP/2190-000002a9", "0?skiptrace") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:31] GosubIf("PJSIP/2190-000002a9", "1?ctset,1():ctclear,1()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [ctset@macro-dial-one:1] Set("PJSIP/2190-000002a9", "DB(CALLTRACE/2197)=2190") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [ctset@macro-dial-one:2] Return("PJSIP/2190-000002a9", "") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:32] Set("PJSIP/2190-000002a9", "D_OPTIONS=HhTtr") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:33] GosubIf("PJSIP/2190-000002a9", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:34] NoOp("PJSIP/2190-000002a9", "Blind Transfer: , Attended Transfer: , User: 2190, Alert Info: ") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:35] ExecIf("PJSIP/2190-000002a9", "1?Set(ALERT_INFO=)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:36] ExecIf("PJSIP/2190-000002a9", "0?Set(ALERT_INFO=)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:37] ExecIf("PJSIP/2190-000002a9", "0?Set(ALERT_INFO=)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:38] ExecIf("PJSIP/2190-000002a9", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:39] ExecIf("PJSIP/2190-000002a9", "0?Set(ALERT_INFO=Normal;volume=)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:40] GosubIf("PJSIP/2190-000002a9", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:41] ExecIf("PJSIP/2190-000002a9", "0?Set(CHANNEL(musicclass)=)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:42] GosubIf("PJSIP/2190-000002a9", "0?qwait,1()") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:43] Set("PJSIP/2190-000002a9", "__CWIGNORE=") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:44] Set("PJSIP/2190-000002a9", "__KEEPCID=TRUE") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:45] GotoIf("PJSIP/2190-000002a9", "0?usegoto,1") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:46] GotoIf("PJSIP/2190-000002a9", "0?godial") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:47] Gosub("PJSIP/2190-000002a9", "sub-presencestate-display,s,1(2197)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@sub-presencestate-display:1] Goto("PJSIP/2190-000002a9", "state-not_set,1") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (sub-presencestate-display,state-not_set,1)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [state-not_set@sub-presencestate-display:1] Set("PJSIP/2190-000002a9", "PRESENCESTATE_DISPLAY=") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [state-not_set@sub-presencestate-display:2] Return("PJSIP/2190-000002a9", "") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:48] Set("PJSIP/2190-000002a9", "CONNECTEDLINE(name,i)=Steve Allen") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:49] Set("PJSIP/2190-000002a9", "CONNECTEDLINE(num)=2197") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:50] Set("PJSIP/2190-000002a9", "D_OPTIONS=HhTtrI") in new stack
[2018-07-23 08:57:54] WARNING[14724][C-00000141] taskprocessor.c: The 'subp:PJSIP/2190-00000054' task processor queue reached 500 scheduled tasks.
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:51] Macro("PJSIP/2190-000002a9", "dialout-one-predial-hook,") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit("PJSIP/2190-000002a9", "") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:52] ExecIf("PJSIP/2190-000002a9", "0?Set(D_OPTIONS=HhtrII)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:53] GotoIf("PJSIP/2190-000002a9", "1?zulunourl") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (macro-dial-one,s,55)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:55] ExecIf("PJSIP/2190-000002a9", "0?Set(ZULU_TYPE=)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:56] GotoIf("PJSIP/2190-000002a9", "1?skippopup") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (macro-dial-one,s,59)
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:59] UserEvent("PJSIP/2190-000002a9", "zulu-call,eventtype:calling,extension:2197,type:,url:,cnam:Simon Wood,cnum:2190,lid:1532332674.1767,from:2190,to:2197,user:") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:60] NoOp("PJSIP/2190-000002a9", "Zulu Finished") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:61] Set("PJSIP/2190-000002a9", "_zuludialopts=") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:62] AGI("PJSIP/2190-000002a9", "zulureplace-one.agi,DSTRING,90") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/zulureplace-one.agi
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] res_agi.c: zulureplace-one.agi,DSTRING,90: DIALSTRING: PJSIP/2197/sip:[email protected]:5060;transport=TLS
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] res_agi.c: zulureplace-one.agi,DSTRING,90: DIALOPTS: HhTtrI
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] res_agi.c: zulureplace-one.agi,DSTRING,90: TIMEOUT: 15
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] res_agi.c: zulureplace-one.agi,DSTRING,90: NEWDIALSTRING: PJSIP/2197/sip:[email protected]:5060;transport=TLS
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] res_agi.c: <PJSIP/2190-000002a9>AGI Script zulureplace-one.agi completed, returning 0
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:63] NoOp("PJSIP/2190-000002a9", "") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:64] ExecIf("PJSIP/2190-000002a9", "0?Set(D_OPTIONS=HhTtrIg)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-dial-one:65] Dial("PJSIP/2190-000002a9", "PJSIP/2197/sip:[email protected]:5060;transport=TLS,15,HhTtrIb(func-apply-sipheaders^s^1)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] app_stack.c: PJSIP/2197-000002aa Internal Gosub(func-apply-sipheaders,s,1) start
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@func-apply-sipheaders:1] UserEvent("PJSIP/2197-000002aa", "zulu-call-b,type:func-apply-sipheaders,to:2197,from:2190") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("PJSIP/2197-000002aa", "Applying SIP Headers to channel") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/2197-000002aa", "SIPHEADERKEYS=") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@func-apply-sipheaders:4] ExecIf("PJSIP/2197-000002aa", "0?Set(Rheader=1)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/2197-000002aa", "0") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] app_while.c: Jumping to priority 8
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("PJSIP/2197-000002aa", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] pbx.c: Executing [s@func-apply-sipheaders:10] Return("PJSIP/2197-000002aa", "") in new stack
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] app_stack.c: Spawn extension (from-internal, 2197, 1) exited non-zero on 'PJSIP/2197-000002aa'
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] app_stack.c: PJSIP/2197-000002aa Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] app_dial.c: Called PJSIP/2197/sip:[email protected]:5060;transport=TLS
[2018-07-23 08:57:54] VERBOSE[29423] netsock2.c: Using SIP RTP Audio TOS bits 184
[2018-07-23 08:57:54] VERBOSE[29423] netsock2.c: Using SIP RTP Audio CoS mark 5
[2018-07-23 08:57:54] VERBOSE[14724][C-00000141] app_dial.c: Connected line update to PJSIP/2190-000002a9 prevented.
[2018-07-23 08:57:55] VERBOSE[14724][C-00000141] app_dial.c: PJSIP/2197-000002aa is ringing
[2018-07-23 08:57:56] VERBOSE[14724][C-00000141] app_dial.c: PJSIP/2197-000002aa answered PJSIP/2190-000002a9
[2018-07-23 08:57:56] VERBOSE[14745][C-00000141] bridge_channel.c: Channel PJSIP/2197-000002aa joined 'simple_bridge' basic-bridge <a0dfba1f-05ff-4650-b3dd-3f5fd199d7b8>
[2018-07-23 08:57:56] VERBOSE[14724][C-00000141] bridge_channel.c: Channel PJSIP/2190-000002a9 joined 'simple_bridge' basic-bridge <a0dfba1f-05ff-4650-b3dd-3f5fd199d7b8>
[2018-07-23 08:57:56] VERBOSE[14724][C-00000141] res_srtp.c: SRTP unprotect failed because of authentication failure 10
[2018-07-23 08:57:59] VERBOSE[14724][C-00000141] res_srtp.c: SRTP unprotect failed because of authentication failure 160
[2018-07-23 08:58:01] VERBOSE[14745][C-00000141] bridge_channel.c: Channel PJSIP/2197-000002aa left 'simple_bridge' basic-bridge <a0dfba1f-05ff-4650-b3dd-3f5fd199d7b8>
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] bridge_channel.c: Channel PJSIP/2190-000002a9 left 'simple_bridge' basic-bridge <a0dfba1f-05ff-4650-b3dd-3f5fd199d7b8>
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] app_macro.c: Spawn extension (macro-dial-one, s, 65) exited non-zero on 'PJSIP/2190-000002a9' in macro 'dial-one'
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] app_macro.c: Spawn extension (macro-exten-vm, s, 26) exited non-zero on 'PJSIP/2190-000002a9' in macro 'exten-vm'
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] pbx.c: Spawn extension (ext-local, 2197, 2) exited non-zero on 'PJSIP/2190-000002a9'
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] pbx.c: Executing [h@ext-local:1] Macro("PJSIP/2190-000002a9", "hangupcall,") in new stack
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/2190-000002a9", "1?theend") in new stack
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/2190-000002a9", "0?Set(CDR(recordingfile)=)") in new stack
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-hangupcall:4] NoOp("PJSIP/2190-000002a9", "PJSIP/2197-000002aa monior file= ") in new stack
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-hangupcall:5] AGI("PJSIP/2190-000002a9", "attendedtransfer-rec-restart.php,PJSIP/2197-000002aa,") in
new stack
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] res_agi.c: <PJSIP/2190-000002a9>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] pbx.c: Executing [s@macro-hangupcall:6] Hangup("PJSIP/2190-000002a9", "") in new stack
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on 'PJSIP/2190-000002a9' in macro 'hangupcall'
[2018-07-23 08:58:01] VERBOSE[14724][C-00000141] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/2190-000002a9'

tonyg · July 23, 2018, 1:06pm

hi, i use sip-tls/srtp also and i get this message on every ongoing call. it annoys me but I do not see any negative impact. It is unrelated to your “one-way” voice issue.

I have had one-way voice problems on srtp before and it always seems to do with one extension not encrypted when the other is (when both phones are configured to use srtp)…do you have opportunistic encryption enabled on the extension? if so, this can lead to some phones using srtp while others not. if you have srtp working properly, you should be able to disable opportunistic encryption on the extension and things will still work. if they break, you have a srtp issue.

system · July 23, 2019, 1:21pm

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