[FreePBX 15 & SPA3102] All circuits busy on outgoing calls

koay_andrew · April 21, 2023, 1:36pm

Hello experts,

FreePBX newbie here. I’ve got FreePBX setup with SPA3102 for my PSTN incoming and outgoing calls.

Incoming works fine and gets routed to the intended extension but I get “All circuits are busy now” on outgoing calls.
Extension to extension calls work fine too.

I’m on:
FreePBX 15.0.37 & Asterisk 16.24.1 (Not updated to the newer version as I could not get SPA to work with it.)
I have 2 PJSIP extensions (one connected on android Linphone app and another through microsip on windows)
SPA3102 using chan_sip trunk (cant get it to work using PJSIP)

I have tried almost all settings and solutions that I can find from this forum but nothing seems to work. What am I doing wrong? Any help would be greatly appreciated.

koay_andrew · April 21, 2023, 1:37pm

Trunk settings:

koay_andrew · April 21, 2023, 1:37pm

Outgoing route settings:

koay_andrew · April 21, 2023, 1:46pm

Asterisk Log when i try to call the local emergency number (999):

53588	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] app_dial.c: SIP/f-pstn-0000006d is circuit-busy	
53589	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] app_dial.c: Everyone is busy/congested at this time (1:0/1/0)	
53590	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:37] NoOp("PJSIP/398-00000625", "Dial failed for some reason with DIALSTATUS = CONGESTION and HANGUPCAUSE = 34") in new stack	
53591	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:38] GotoIf("PJSIP/398-00000625", "0?continue,1:s-CONGESTION,1") in new stack	
53592	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx_builtins.c: Goto (macro-dialout-trunk,s-CONGESTION,1)	
53593	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:1] Set("PJSIP/398-00000625", "RC=34") in new stack	
53594	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:2] Goto("PJSIP/398-00000625", "34,1") in new stack	
53595	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx_builtins.c: Goto (macro-dialout-trunk,34,1)	
53596	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:1] Goto("PJSIP/398-00000625", "continue,1") in new stack	
53597	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx_builtins.c: Goto (macro-dialout-trunk,continue,1)	
53598	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/398-00000625", "TRUNK Dial failed due to CONGESTION HANGUPCAUSE: 34 - failing through to other trunks") in new stack	
53599	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:2] ExecIf("PJSIP/398-00000625", "1?Set(CALLERID(number)=398)") in new stack	
53600	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:13] Macro("PJSIP/398-00000625", "outisbusy,") in new stack	
53601	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:1] Progress("PJSIP/398-00000625", "") in new stack	
53602	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:2] GotoIf("PJSIP/398-00000625", "0?emergency,1") in new stack	
53603	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:3] GotoIf("PJSIP/398-00000625", "0?intracompany,1") in new stack	
53604	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:4] Playback("PJSIP/398-00000625", "all-circuits-busy-now&please-try-call-later, noanswer") in new stack	
53605	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] file.c: <PJSIP/398-00000625> Playing 'all-circuits-busy-now.g722' (language 'en_GB')	
53606	[2023-04-21 21:22:06] VERBOSE[2626] chan_sip.c: Really destroying SIP dialog '[email protected]:5160' Method: INVITE	
53607	[2023-04-21 21:22:07] VERBOSE[13774][C-00000623] file.c: <PJSIP/398-00000625> Playing 'please-try-call-later.g722' (language 'en_GB')	
53608	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:5] Congestion("PJSIP/398-00000625", "20") in new stack	
53609	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] app_macro.c: Spawn extension (macro-outisbusy, s, 5) exited non-zero on 'PJSIP/398-00000625' in macro 'outisbusy'	
53610	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Spawn extension (from-internal, 9999, 13) exited non-zero on 'PJSIP/398-00000625'	
53611	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:1] Macro("PJSIP/398-00000625", "hangupcall") in new stack	
53612	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:1] GotoIf("PJSIP/398-00000625", "1?theend") in new stack	
53613	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx_builtins.c: Goto (macro-hangupcall,s,3)	
53614	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:3] ExecIf("PJSIP/398-00000625", "0?Set(CDR(recordingfile)=)") in new stack	
53615	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:4] Hangup("PJSIP/398-00000625", "") in new stack	
53616	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/398-00000625' in macro 'hangupcall'	
53617	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/398-00000625'	
53618	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] app_stack.c: PJSIP/398-00000625 Internal Gosub(crm-hangup,s,1) start	
53619	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/398-00000625", "Sending Hangup to CRM") in new stack	
53620	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:2] NoOp("PJSIP/398-00000625", "HANGUP CAUSE: 34") in new stack	
53621	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:3] ExecIf("PJSIP/398-00000625", "0?Set(__CRM_VOICEMAIL=)") in new stack	
53622	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:4] NoOp("PJSIP/398-00000625", "MASTER CHANNEL: 1682083324.1682 = 1682083324.1682") in new stack	
53623	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:5] GotoIf("PJSIP/398-00000625", "0?return") in new stack	
53624	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:6] Set("PJSIP/398-00000625", "__CRM_HANGUP=1") in new stack	
53625	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:7] AGI("PJSIP/398-00000625", "agi://127.0.0.1/sangomacrm.agi") in new stack	
53626	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] res_agi.c: <PJSIP/398-00000625>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0	
53627	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [[email protected]:8] Return("PJSIP/398-00000625", "") in new stack	
53628	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] app_stack.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/398-00000625'	
53629	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] app_stack.c: PJSIP/398-00000625 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=	
53630	[2023-04-21 21:22:13] VERBOSE[2626] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.0.245:5160:	
53631	OPTIONS sip:[email protected]:5160 SIP/2.0	
53632	Via: SIP/2.0/UDP 192.168.0.172:5160;branch=z9hG4bK5aec526b	
53633	Max-Forwards: 70	
53634	From: "Unknown" <sip:[email protected]:5160>;tag=as2bc0eaeb	
53635	To: <sip:[email protected]:5160>	
53636	Contact: <sip:[email protected]:5160>	
53637	Call-ID: [email protected]:5160	
53638	CSeq: 102 OPTIONS	
53639	User-Agent: FPBX-15.0.37(16.24.1)	
53640	Date: Fri, 21 Apr 2023 13:22:13 GMT	
53641	Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE	
53642	Supported: replaces, timer	
53643	Content-Length: 0	
53644		
53645		
53646	---	
53647	[2023-04-21 21:22:13] VERBOSE[2626] chan_sip.c:	
53648	<--- SIP read from UDP:192.168.0.245:5160 --->	
53649	SIP/2.0 200 OK	
53650	To: <sip:[email protected]:5160>;tag=a19cce6da2ee70cai1	
53651	From: "Unknown" <sip:[email protected]:5160>;tag=as2bc0eaeb	
53652	Call-ID: [email protected]:5160	
53653	CSeq: 102 OPTIONS	
53654	Via: SIP/2.0/UDP 192.168.0.172:5160;branch=z9hG4bK5aec526b	
53655	Server: Linksys/SPA3102-5.2.13(GW002)	
53656	Content-Length: 0	
53657	Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER	
53658	Supported: x-sipura, replaces	
53659		
53660	<------------->	
53661	[2023-04-21 21:22:13] VERBOSE[2626] chan_sip.c: --- (10 headers 0 lines) ---	
53662	[2023-04-21 21:22:13] VERBOSE[2626] chan_sip.c: Really destroying SIP dialog '[email protected]:5160' Method: OPTIONS

david55 · April 21, 2023, 2:07pm

The log starts too late.

mcgrathr · April 21, 2023, 3:00pm

What’s line status on SPA info tab?

koay_andrew · April 22, 2023, 1:07am

sorry about that. here’s the full log (1/2):

15671	[2023-04-22 09:04:19] VERBOSE[26706] netsock2.c: Using SIP RTP Audio TOS bits 184	
15672	[2023-04-22 09:04:19] VERBOSE[26706] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.	
15673	[2023-04-22 09:04:19] VERBOSE[26706] netsock2.c: Using SIP RTP Audio CoS mark 5	
15674	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] Macro("PJSIP/398-0000066a", "user-callerid,LIMIT,EXTERNAL,") in new stack	
15675	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] Set("PJSIP/398-0000066a", "TOUCH_MONITOR=1682125459.1752") in new stack	
15676	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] Set("PJSIP/398-0000066a", "CHANCONTEXT=") in new stack	
15677	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:3] Progress("PJSIP/398-0000066a", "") in new stack	
15678	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:4] Set("PJSIP/398-0000066a", "CHANCONTEXT=") in new stack	
15679	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:5] Set("PJSIP/398-0000066a", "CHANEXTENCONTEXT=398-0000066a") in new stack	
15680	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:6] Set("PJSIP/398-0000066a", "CHANEXTEN=398-0000066a") in new stack	
15681	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:7] Set("PJSIP/398-0000066a", "CALLERID(number)=398") in new stack	
15682	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:8] Set("PJSIP/398-0000066a", "AMPUSER=398") in new stack	
15683	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:9] Set("PJSIP/398-0000066a", "HOTDESCKCHAN=398-0000066a") in new stack	
15684	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:10] Set("PJSIP/398-0000066a", "HOTDESKEXTEN=398") in new stack	
15685	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:11] Set("PJSIP/398-0000066a", "HOTDESKCALL=0") in new stack	
15686	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:12] ExecIf("PJSIP/398-0000066a", "0?Set(HOTDESKCALL=1)") in new stack	
15687	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:13] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERID(name)=)") in new stack	
15688	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:14] GotoIf("PJSIP/398-0000066a", "0?report") in new stack	
15689	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:15] ExecIf("PJSIP/398-0000066a", "1?Set(REALCALLERIDNUM=398)") in new stack	
15690	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:16] Set("PJSIP/398-0000066a", "AMPUSER=398") in new stack	
15691	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:17] GotoIf("PJSIP/398-0000066a", "0?limit") in new stack	
15692	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:18] Set("PJSIP/398-0000066a", "AMPUSERCIDNAME=Test") in new stack	
15693	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:19] ExecIf("PJSIP/398-0000066a", "0?Set(__CIDMASQUERADING=TRUE)") in new stack	
15694	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:20] GotoIf("PJSIP/398-0000066a", "0?report") in new stack	
15695	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:21] Set("PJSIP/398-0000066a", "AMPUSERCID=398") in new stack	
15696	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:22] Set("PJSIP/398-0000066a", "__DIAL_OPTIONS=HhTtr") in new stack	
15697	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:23] Set("PJSIP/398-0000066a", "CALLERID(all)="Test" <398>") in new stack	
15698	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:24] ExecIf("PJSIP/398-0000066a", "0?Set(CUSDIAL=)") in new stack	
15699	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:25] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERID(all)="Test" <398>)") in new stack	
15700	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:26] GotoIf("PJSIP/398-0000066a", "0?limit") in new stack	
15701	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:27] ExecIf("PJSIP/398-0000066a", "1?Set(GROUP(concurrency_limit)=398)") in new stack	
15702	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:28] ExecIf("PJSIP/398-0000066a", "0?Set(CHANNEL(language)=)") in new stack	
15703	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:29] NoOp("PJSIP/398-0000066a", "Macro Depth is 1") in new stack	
15704	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:30] GotoIf("PJSIP/398-0000066a", "1?report2:macroerror") in new stack	
15705	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (macro-user-callerid,s,31)	
15706	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:31] GotoIf("PJSIP/398-0000066a", "1?continue") in new stack	
15707	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (macro-user-callerid,s,50)	
15708	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:50] Set("PJSIP/398-0000066a", "CALLERID(number)=398") in new stack	
15709	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:51] Set("PJSIP/398-0000066a", "CALLERID(name)=Test") in new stack	
15710	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:52] GotoIf("PJSIP/398-0000066a", "0?cnum") in new stack	
15711	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:53] Set("PJSIP/398-0000066a", "CDR(cnam)=Test") in new stack	
15712	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:54] Set("PJSIP/398-0000066a", "CDR(cnum)=398") in new stack	
15713	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:55] Set("PJSIP/398-0000066a", "CHANNEL(language)=en_GB") in new stack	
15714	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] Gosub("PJSIP/398-0000066a", "sub-record-check,s,1(out,9999,never)") in new stack	
15715	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] GotoIf("PJSIP/398-0000066a", "0?initialized") in new stack	
15716	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] Set("PJSIP/398-0000066a", "__REC_STATUS=INITIALIZED") in new stack	
15717	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:3] Set("PJSIP/398-0000066a", "NOW=1682125459") in new stack	
15718	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:4] Set("PJSIP/398-0000066a", "__DAY=22") in new stack	
15719	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:5] Set("PJSIP/398-0000066a", "__MONTH=04") in new stack	
15720	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:6] Set("PJSIP/398-0000066a", "__YEAR=2023") in new stack	
15721	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:7] Set("PJSIP/398-0000066a", "__TIMESTR=20230422-090419") in new stack	
15722	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:8] Set("PJSIP/398-0000066a", "__FROMEXTEN=398") in new stack	
15723	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:9] Set("PJSIP/398-0000066a", "__MON_FMT=wav") in new stack	
15724	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:10] NoOp("PJSIP/398-0000066a", "Recordings initialized") in new stack	
15725	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:11] ExecIf("PJSIP/398-0000066a", "0?Set(ARG3=dontcare)") in new stack	
15726	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:12] Set("PJSIP/398-0000066a", "REC_POLICY_MODE_SAVE=") in new stack	
15727	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:13] ExecIf("PJSIP/398-0000066a", "0?Set(REC_STATUS=NO)") in new stack	
15728	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:14] GotoIf("PJSIP/398-0000066a", "3?checkaction") in new stack	
15729	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (sub-record-check,s,17)	
15730	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:17] GotoIf("PJSIP/398-0000066a", "1?sub-record-check,out,1") in new stack	
15731	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (sub-record-check,out,1)	
15732	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/398-0000066a", "Outbound Recording Check from 398 to 9999") in new stack	
15733	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] Set("PJSIP/398-0000066a", "RECMODE=dontcare") in new stack	
15734	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:3] ExecIf("PJSIP/398-0000066a", "1?Goto(routewins)") in new stack	
15735	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (sub-record-check,out,7)	
15736	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:7] Gosub("PJSIP/398-0000066a", "recordcheck,1(never,out,9999)") in new stack	
15737	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/398-0000066a", "Starting recording check against never") in new stack	
15738	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] Goto("PJSIP/398-0000066a", "never") in new stack	
15739	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (sub-record-check,recordcheck,14)	
15740	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:14] Set("PJSIP/398-0000066a", "__REC_POLICY_MODE=NEVER") in new stack	
15741	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:15] Goto("PJSIP/398-0000066a", "stoprec") in new stack	
15742	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (sub-record-check,recordcheck,26)	
15743	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:26] NoOp("PJSIP/398-0000066a", "Stopping recording: out, 9999") in new stack	
15744	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:27] Set("PJSIP/398-0000066a", "__REC_STATUS=STOPPED") in new stack	
15745	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:28] System("PJSIP/398-0000066a", "/var/lib/asterisk/bin/stoprecording.php "PJSIP/398-0000066a"") in new stack	
15746	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:29] Return("PJSIP/398-0000066a", "") in new stack	
15747	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:8] Return("PJSIP/398-0000066a", "") in new stack	
15748	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]l:3] ExecIf("PJSIP/398-0000066a", "0 ?Set(CDR(accountcode)=)") in new stack	
15749	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:4] Set("PJSIP/398-0000066a", "_ROUTEID=2") in new stack	
15750	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:5] Set("PJSIP/398-0000066a", "_ROUTENAME=spa3102-1") in new stack	
15751	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:6] Set("PJSIP/398-0000066a", "MOHCLASS=default") in new stack	
15752	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:7] ExecIf("PJSIP/398-0000066a", "1?Set(TRUNKCIDOVERRIDE=f-pstn)") in new stack	
15753	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:8] Set("PJSIP/398-0000066a", "_CALLERIDNAMEINTERNAL=Test") in new stack	
15754	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:9] Set("PJSIP/398-0000066a", "_CALLERIDNUMINTERNAL=398") in new stack	
15755	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:10] Set("PJSIP/398-0000066a", "_EMAILNOTIFICATION=FALSE") in new stack	
15756	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:11] Set("PJSIP/398-0000066a", "_NODEST=") in new stack	
15757	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:12] Macro("PJSIP/398-0000066a", "dialout-trunk,1,999,,off") in new stack	
15758	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] Set("PJSIP/398-0000066a", "DIAL_TRUNK=1") in new stack	
15759	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] ExecIf("PJSIP/398-0000066a", "0?Set(DIAL_OPTIONS=Hhtr)") in new stack	
15760	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:3] GosubIf("PJSIP/398-0000066a", "0?sub-pincheck,s,1()") in new stack	
15761	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:4] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERID(num)=398)") in new stack	
15762	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:5] GotoIf("PJSIP/398-0000066a", "0?disabletrunk,1") in new stack	
15763	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:6] Set("PJSIP/398-0000066a", "DIAL_NUMBER=999") in new stack	
15764	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:7] Set("PJSIP/398-0000066a", "DIAL_TRUNK_OPTIONS=HhTtr") in new stack	
15765	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:8] Set("PJSIP/398-0000066a", "OUTBOUND_GROUP=OUT_1") in new stack	
15766	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:9] Set("PJSIP/398-0000066a", "DIAL_TRUNK_OPTIONS=T") in new stack	
15767	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:10] GotoIf("PJSIP/398-0000066a", "0?nomax") in new stack	
15768	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:11] GotoIf("PJSIP/398-0000066a", "0?chanfull") in new stack	
15769	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:12] GotoIf("PJSIP/398-0000066a", "0?skipoutcid") in new stack	
15770	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:13] Macro("PJSIP/398-0000066a", "outbound-callerid,1") in new stack	
15771	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/398-0000066a", "398") in new stack	
15772	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] NoOp("PJSIP/398-0000066a", "") in new stack	
15773	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:3] NoOp("PJSIP/398-0000066a", "off") in new stack	
15774	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:4] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERPRES(name-pres)=)") in new stack	
15775	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:5] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERPRES(num-pres)=)") in new stack	
15776	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:6] Set("PJSIP/398-0000066a", "HOTDESCKCHAN=398-0000066a") in new stack	
15777	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:7] Set("PJSIP/398-0000066a", "HOTDESKEXTEN=398") in new stack	
15778	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:8] Set("PJSIP/398-0000066a", "HOTDESKCALL=0") in new stack	
15779	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:9] ExecIf("PJSIP/398-0000066a", "0?Set(HOTDESKCALL=1)") in new stack	
15780	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:10] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERID(name)=)") in new stack	
15781	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:11] Set("PJSIP/398-0000066a", "ALLOWTHISROUTE=NO") in new stack	
15782	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:12] ExecIf("PJSIP/398-0000066a", "0?Set(ALLOWTHISROUTE=YES)") in new stack	
15783	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:13] ExecIf("PJSIP/398-0000066a", "0?Hangup()") in new stack	
15784	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:14] ExecIf("PJSIP/398-0000066a", "0?Set(REALCALLERIDNUM=398)") in new stack	
15785	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:15] ExecIf("PJSIP/398-0000066a", "0?Set(AMPUSER=398)") in new stack	
15786	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:16] GotoIf("PJSIP/398-0000066a", "1?normcid") in new stack	
15787	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (macro-outbound-callerid,s,20)	
15788	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:20] Set("PJSIP/398-0000066a", "USEROUTCID=") in new stack	
15789	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:21] Set("PJSIP/398-0000066a", "EMERGENCYCID=") in new stack	
15790	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:22] ExecIf("PJSIP/398-0000066a", "0?Set(SCDEXT=YES)") in new stack	
15791	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:23] ExecIf("PJSIP/398-0000066a", "0?Set(EMERGENCYCID=)") in new stack	
15792	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:24] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERID(name)=)") in new stack	
15793	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:25] ExecIf("PJSIP/398-0000066a", "0?Set(EMERGENCYCID=)") in new stack	
15794	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:26] Set("PJSIP/398-0000066a", "TRUNKOUTCID=hidden") in new stack	
15795	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:27] GotoIf("PJSIP/398-0000066a", "1?trunkcid") in new stack	
15796	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (macro-outbound-callerid,s,33)	
15797	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:33] ExecIf("PJSIP/398-0000066a", "1?Set(CALLERID(all)=hidden)") in new stack	
15798	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:34] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERID(all)=)") in new stack	
15799	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:35] ExecIf("PJSIP/398-0000066a", "1?Set(CALLERID(all)=f-pstn)") in new stack	
15800	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:36] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERID(all)=398)") in new stack	
15801	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:37] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERID(all)=398)") in new stack	
15802	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:38] Set("PJSIP/398-0000066a", "TIOHIDE=no") in new stack	
15803	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:39] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack	
15804	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:40] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack	
15805	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:41] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack	
15806	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:42] ExecIf("PJSIP/398-0000066a", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack	
15807	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:43] Set("PJSIP/398-0000066a", "CDR(outbound_cnum)=") in new stack	
15808	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:44] Set("PJSIP/398-0000066a", "CDR(outbound_cnam)=f-pstn") in new stack	
15809	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:14] GosubIf("PJSIP/398-0000066a", "0?sub-flp-1,s,1()") in new stack	
15810	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:15] Set("PJSIP/398-0000066a", "OUTNUM=999") in new stack	
15811	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:16] Set("PJSIP/398-0000066a", "custom=SIP/f-pstn") in new stack	
15812	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:17] ExecIf("PJSIP/398-0000066a", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack	
15813	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:18] ExecIf("PJSIP/398-0000066a", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack	
15814	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:19] GotoIf("PJSIP/398-0000066a", "1?gocall") in new stack	
15815	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (macro-dialout-trunk,s,21)	
15816	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:21] Macro("PJSIP/398-0000066a", "dialout-trunk-predial-hook,") in new stack	
15817	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] MacroExit("PJSIP/398-0000066a", "") in new stack	
15818	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:22] GotoIf("PJSIP/398-0000066a", "0?skipcrm") in new stack	
15819	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:23] Set("PJSIP/398-0000066a", "__CRM_DIRECTION=OUTBOUND") in new stack	
15820	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:24] Set("PJSIP/398-0000066a", "__CRM_DESTINATION=999") in new stack	
15821	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:25] Set("PJSIP/398-0000066a", "__CRM_SOURCE=398") in new stack	
15822	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:26] AGI("PJSIP/398-0000066a", "agi://127.0.0.1/sangomacrm.agi") in new stack	
15823	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] res_agi.c: <PJSIP/398-0000066a>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0	
15824	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:27] Set("PJSIP/398-0000066a", "CHANNEL(hangup_handler_push)=crm-hangup,s,1") in new stack	
15825	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:28] NoOp("PJSIP/398-0000066a", "CRM Finished") in new stack	
15826	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:29] GotoIf("PJSIP/398-0000066a", "0?bypass,1") in new stack	
15827	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:30] ExecIf("PJSIP/398-0000066a", "1?Set(CONNECTEDLINE(num,i)=999)") in new stack	
15828	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:31] ExecIf("PJSIP/398-0000066a", "1?Set(CONNECTEDLINE(name,i)=CID:)") in new stack	
15829	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:32] ExecIf("PJSIP/398-0000066a", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden))") in new stack	
15830	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:33] GotoIf("PJSIP/398-0000066a", "0?customtrunk") in new stack	
15831	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:34] ExecIf("PJSIP/398-0000066a", "0?Set(DIAL_TRUNK_OPTIONS=)") in new stack	
15832	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:35] Set("PJSIP/398-0000066a", "HASH(__SIPHEADERS,Alert-Info)=unset") in new stack	
15833	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:36] Dial("PJSIP/398-0000066a", "SIP/f-pstn/999,300,Tb(func-apply-sipheaders^s^1,(1))U(sub-send-obroute-email^999^9999^1^1682125459^f-pstn^)") in new stack

koay_andrew · April 22, 2023, 1:08am

here’s the full log (2/2):

15834	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] netsock2.c: Using SIP RTP TOS bits 184	
15835	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] netsock2.c: Using SIP RTP CoS mark 5	
15836	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] app_stack.c: SIP/f-pstn-0000006e Internal Gosub(func-apply-sipheaders,s,1(1)) start	
15837	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] ExecIf("SIP/f-pstn-0000006e", "0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack	
15838	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] NoOp("SIP/f-pstn-0000006e", "Applying SIP Headers to channel SIP/f-pstn-0000006e") in new stack	
15839	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:3] Set("SIP/f-pstn-0000006e", "TECH=SIP") in new stack	
15840	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:4] Set("SIP/f-pstn-0000006e", "SIPHEADERKEYS=Alert-Info") in new stack	
15841	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:5] While("SIP/f-pstn-0000006e", "1") in new stack	
15842	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:6] Set("SIP/f-pstn-0000006e", "sipheader=unset") in new stack	
15843	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:7] ExecIf("SIP/f-pstn-0000006e", "1?SIPRemoveHeader(Alert-Info:)") in new stack	
15844	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:8] ExecIf("SIP/f-pstn-0000006e", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack	
15845	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:9] ExecIf("SIP/f-pstn-0000006e", "0?Set(sipheader=<http://127.0.0.1>;info=unset)") in new stack	
15846	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:10] ExecIf("SIP/f-pstn-0000006e", "0?Set(sipheader=<http://127.0.0.1>unset)") in new stack	
15847	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:11] ExecIf("SIP/f-pstn-0000006e", "0?SIPAddHeader(Alert-Info:unset)") in new stack	
15848	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:12] ExecIf("SIP/f-pstn-0000006e", "0?Set(PJSIP_HEADER(add,Alert-Info)=unset)") in new stack	
15849	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:13] EndWhile("SIP/f-pstn-0000006e", "") in new stack	
15850	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:5] While("SIP/f-pstn-0000006e", "0") in new stack	
15851	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:14] Return("SIP/f-pstn-0000006e", "") in new stack	
15852	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] app_stack.c: Spawn extension (from-trunk, 9999, 1) exited non-zero on 'SIP/f-pstn-0000006e'	
15853	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] app_stack.c: SIP/f-pstn-0000006e Internal Gosub(func-apply-sipheaders,s,1(1)) complete GOSUB_RETVAL=	
15854	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] chan_sip.c: Audio is at 18390	
15855	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] chan_sip.c: Adding codec ulaw to SDP	
15856	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.0.245:5160:	
15857	INVITE sip:[email protected]:5160 SIP/2.0	
15858	Via: SIP/2.0/UDP 192.168.0.172:5160;branch=z9hG4bK1111bf4d	
15859	Max-Forwards: 70	
15860	From: "f-pstn" <sip:[email protected]:5160>;tag=as29542345	
15861	To: <sip:[email protected]:5160>	
15862	Contact: <sip:[email protected]:5160>	
15863	Call-ID: [email protected]:5160	
15864	CSeq: 102 INVITE	
15865	User-Agent: FPBX-15.0.37(16.24.1)	
15866	Date: Sat, 22 Apr 2023 01:04:20 GMT	
15867	Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE	
15868	Supported: replaces, timer	
15869	Content-Type: application/sdp	
15870	Content-Length: 186	
15871		
15872	v=0	
15873	o=root 1984440537 1984440537 IN IP4 192.168.0.172	
15874	s=Asterisk PBX 16.24.1	
15875	c=IN IP4 192.168.0.172	
15876	t=0 0	
15877	m=audio 18390 RTP/AVP 0	
15878	a=rtpmap:0 PCMU/8000	
15879	a=maxptime:150	
15880	a=sendrecv	
15881		
15882	---	
15883	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] app_dial.c: Called SIP/f-pstn/999	
15884	[2023-04-22 09:04:20] VERBOSE[2626] chan_sip.c:	
15885	<--- SIP read from UDP:192.168.0.245:5160 --->	
15886	SIP/2.0 100 Trying	
15887	To: <sip:[email protected]:5160>	
15888	From: "f-pstn" <sip:[email protected]:5160>;tag=as29542345	
15889	Call-ID: [email protected]:5160	
15890	CSeq: 102 INVITE	
15891	Via: SIP/2.0/UDP 192.168.0.172:5160;branch=z9hG4bK1111bf4d	
15892	Server: Linksys/SPA3102-5.2.13(GW002)	
15893	Content-Length: 0	
15894		
15895	<------------->	
15896	[2023-04-22 09:04:20] VERBOSE[2626] chan_sip.c: --- (8 headers 0 lines) ---	
15897	[2023-04-22 09:04:20] VERBOSE[2626] chan_sip.c:	
15898	<--- SIP read from UDP:192.168.0.245:5160 --->	
15899	SIP/2.0 503 Service Unavailable	
15900	To: <sip:[email protected]:5160>;tag=a19cce6da2ee70cai1	
15901	From: "f-pstn" <sip:[email protected]:5160>;tag=as29542345	
15902	Call-ID: [email protected]:5160	
15903	CSeq: 102 INVITE	
15904	Via: SIP/2.0/UDP 192.168.0.172:5160;branch=z9hG4bK1111bf4d	
15905	Server: Linksys/SPA3102-5.2.13(GW002)	
15906	Content-Length: 0	
15907		
15908	<------------->	
15909	[2023-04-22 09:04:20] VERBOSE[2626] chan_sip.c: --- (8 headers 0 lines) ---	
15910	[2023-04-22 09:04:20] VERBOSE[2626][C-00000667] chan_sip.c: Got SIP response 503 "Service Unavailable" back from 192.168.0.245:5160	
15911	[2023-04-22 09:04:20] VERBOSE[2626][C-00000667] chan_sip.c: Transmitting (no NAT) to 192.168.0.245:5160:	
15912	ACK sip:[email protected]:5160 SIP/2.0	
15913	Via: SIP/2.0/UDP 192.168.0.172:5160;branch=z9hG4bK1111bf4d	
15914	Max-Forwards: 70	
15915	From: "f-pstn" <sip:[email protected]:5160>;tag=as29542345	
15916	To: <sip:[email protected]:5160>;tag=a19cce6da2ee70cai1	
15917	Contact: <sip:[email protected]:5160>	
15918	Call-ID: [email protected]:5160	
15919	CSeq: 102 ACK	
15920	User-Agent: FPBX-15.0.37(16.24.1)	
15921	Content-Length: 0	
15922		
15923		
15924	---	
15925	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] app_dial.c: SIP/f-pstn-0000006e is circuit-busy	
15926	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] app_dial.c: Everyone is busy/congested at this time (1:0/1/0)	
15927	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:37] NoOp("PJSIP/398-0000066a", "Dial failed for some reason with DIALSTATUS = CONGESTION and HANGUPCAUSE = 34") in new stack	
15928	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:38] GotoIf("PJSIP/398-0000066a", "0?continue,1:s-CONGESTION,1") in new stack	
15929	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (macro-dialout-trunk,s-CONGESTION,1)	
15930	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] Set("PJSIP/398-0000066a", "RC=34") in new stack	
15931	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] Goto("PJSIP/398-0000066a", "34,1") in new stack	
15932	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (macro-dialout-trunk,34,1)	
15933	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] Goto("PJSIP/398-0000066a", "continue,1") in new stack	
15934	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (macro-dialout-trunk,continue,1)	
15935	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/398-0000066a", "TRUNK Dial failed due to CONGESTION HANGUPCAUSE: 34 - failing through to other trunks") in new stack	
15936	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] ExecIf("PJSIP/398-0000066a", "1?Set(CALLERID(number)=398)") in new stack	
15937	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:13] Macro("PJSIP/398-0000066a", "outisbusy,") in new stack	
15938	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] Progress("PJSIP/398-0000066a", "") in new stack	
15939	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] GotoIf("PJSIP/398-0000066a", "0?emergency,1") in new stack	
15940	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:3] GotoIf("PJSIP/398-0000066a", "0?intracompany,1") in new stack	
15941	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:4] Playback("PJSIP/398-0000066a", "all-circuits-busy-now&please-try-call-later, noanswer") in new stack	
15942	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] file.c: <PJSIP/398-0000066a> Playing 'all-circuits-busy-now.g722' (language 'en_GB')	
15943	[2023-04-22 09:04:21] VERBOSE[2626] chan_sip.c: Really destroying SIP dialog '[email protected]:5160' Method: INVITE	
15944	[2023-04-22 09:04:21] VERBOSE[22282][C-00000667] file.c: <PJSIP/398-0000066a> Playing 'please-try-call-later.g722' (language 'en_GB')	
15945	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:5] Congestion("PJSIP/398-0000066a", "20") in new stack	
15946	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] app_macro.c: Spawn extension (macro-outisbusy, s, 5) exited non-zero on 'PJSIP/398-0000066a' in macro 'outisbusy'	
15947	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Spawn extension (from-internal, 9999, 13) exited non-zero on 'PJSIP/398-0000066a'	
15948	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] Macro("PJSIP/398-0000066a", "hangupcall") in new stack	
15949	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] GotoIf("PJSIP/398-0000066a", "1?theend") in new stack	
15950	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx_builtins.c: Goto (macro-hangupcall,s,3)	
15951	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:3] ExecIf("PJSIP/398-0000066a", "0?Set(CDR(recordingfile)=)") in new stack	
15952	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:4] Hangup("PJSIP/398-0000066a", "") in new stack	
15953	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/398-0000066a' in macro 'hangupcall'	
15954	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/398-0000066a'	
15955	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] app_stack.c: PJSIP/398-0000066a Internal Gosub(crm-hangup,s,1) start	
15956	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:1] NoOp("PJSIP/398-0000066a", "Sending Hangup to CRM") in new stack	
15957	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:2] NoOp("PJSIP/398-0000066a", "HANGUP CAUSE: 34") in new stack	
15958	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:3] ExecIf("PJSIP/398-0000066a", "0?Set(__CRM_VOICEMAIL=)") in new stack	
15959	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:4] NoOp("PJSIP/398-0000066a", "MASTER CHANNEL: 1682125459.1752 = 1682125459.1752") in new stack	
15960	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:5] GotoIf("PJSIP/398-0000066a", "0?return") in new stack	
15961	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:6] Set("PJSIP/398-0000066a", "__CRM_HANGUP=1") in new stack	
15962	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:7] AGI("PJSIP/398-0000066a", "agi://127.0.0.1/sangomacrm.agi") in new stack	
15963	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] res_agi.c: <PJSIP/398-0000066a>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0	
15964	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [[email protected]:8] Return("PJSIP/398-0000066a", "") in new stack	
15965	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] app_stack.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/398-0000066a'	
15966	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] app_stack.c: PJSIP/398-0000066a Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
15967	[2023-04-22 09:04:42] VERBOSE[2626] chan_sip.c: Really destroying SIP dialog '[email protected]' Method: REGISTER

koay_andrew · April 22, 2023, 1:12am

it’s registered. i can receive incoming calls.

Stewart1 · April 22, 2023, 4:54am

Try setting Line-In-Use Voltage to 12 and retest. If no luck, but the SPA response to INVITE is now other than 503, post a new log.

I don’t know why your Line Voltage is so low. A traditional landline would be ~48 V. What device make/model is providing the line (cable MTA, fiber ONT, etc.)? Do you have any non-voice devices connected (fax machine, alarm system, medical device, etc.)?

It is not a good idea to use an emergency number for this kind of testing. In most countries, if you make an emergency call and the dispatcher can’t hear or be heard, they will dispatch police and/or paramedics to your location, as it is common for emergency callers to be unable to speak (choking, stroke) or not wish to speak, e.g. calling surreptitiously in a holdup. You may be fined for making such a call when there is no emergency. Even if not, be aware that your call might delay the response to someone else’s life threatening emergency.

Instead, to avoid posting a personal number on a public forum, test using a company number that is answered by an IVR (not disturbing a human), for example 03 2264 2264 (KL Hilton).

After your system is working reliably for normal calls, if you want to confirm that your route to 999 is working, I recommend first calling your police non-emergency number and ask for permission. They will tell you a good time to call, when emergency traffic is usually low. When you call, immediately tell the dispatcher that you don’t have an emergency, are testing a new phone system and is it ok to proceed? You might ask if your physical address is correctly displayed. Don’t hang up until they confirm that there is no emergency, then thank them and end the call.

Your system is set up to require dialing 9 before an outside number. Modern systems generally don’t do that; it causes many problems (for example, not being able to return a call from device history). If for some reason you decide to keep this pattern, you should set your Emergency route so that 999 and 9999 both work, as someone panicking may forget to dial the initial 9.

I see that you have PSTN Answer Delay set to 0. In most countries, that will prevent caller ID from working properly. If your PSTN service has caller ID but the calling number is not appearing in FreePBX, try setting it to 4. You may also have to change the caller ID related settings on the Regional page, though I don’t know what format is used in Malaysia.

koay_andrew · April 22, 2023, 5:33am

Thank you sir! That did the trick. Outgoing is working well now.

MTSFB1716R1_PABX_PSTN (mcmc.gov.my)
This is the technical code for PABX private set by the Malaysia’s communications regulatory body. I don’t really understand the technical terms but I think using 9 for dialing out is a must?

Now that you mention it. Yes, caller ID isn’t working too. I have tried every option available in the “Caller ID method” and “FSK standard” section with “Answer Delay” set to 4. No luck with any of these options.

Here’s the technical specs for caller ID:
Microsoft Word - SKMM FTS P ACLIP.doc (mcmc.gov.my)

Appreciate your help on this issue as well.

Thanks again!

Stewart1 · April 22, 2023, 7:03am

Just guessing here, the double ring sent before the caller ID data is confusing the SPA.

Based on the spec, I am fairly sure that Caller ID Method should be Bellcore and Caller ID FSK Standard should be bell 202. Leave PSTN Answer Delay at 4. Then, try setting Ring Timeout to 384 ms or 256 ms, and/or Ring Validation Time to 200 ms. Possibly, also try with Ring Indication Delay at 256 ms or 0.

If no luck, I’m hoping that setting up Syslog Server and Debug Server will show you when the SPA starts listening for the CSS and compare that to when it’s actually sent. If wrong, that may guide you to adjusting the various ring timing parameters. If correct, I don’t know what the trouble is; perhaps you can capture the audio on the line, e.g. with a butt set and we can see whether the format matches the spec you posted.

Stewart1 · April 22, 2023, 7:11am

I found this:

for a different device but with the same ring timing parameters, which interprets them differently from my understanding. If my above suggestions don’t help, try adjusting timing per this manual.

koay_andrew · April 22, 2023, 8:34am

Stewart,

Thanks for getting back. Call ID method, FSK std and delay set as adviced.

I tried every option with the ring timeout, validation time and indication delay. No luck.

How to setup a syslog or debug server? Do I do it on the SPA or the PBX?

mcgrathr · April 22, 2023, 1:06pm

It seems SPA never receive any call from FreePBX, as on SPA screenshots SIP setting UDP port has a PJSIP default value and on FreePBX is configured as Trunk SIP setting, could check on FreePBX “SIP server port” value.
Otherwise should capture packets.

koay_andrew · April 22, 2023, 1:29pm

I’m using the default FPBX port values: chan_sip 5160 and chan_pjsip 5060.

Incoming and outgoing calls working now except caller ID.

koay_andrew · April 22, 2023, 2:47pm

Stewart,

I captured the audio but doesn’t seem to be anything between the first and second ring.

This is what the first 3 pulse looks like.

I don’t usually use this line (bundled with fibre internet) so I tested with a phone and caller ID doesnt work as well for the phone.

I have called my ISP and now they are sending a technician over to check. Will test again after they rectify the issue.

Thanks for the trouble.

system · May 2, 2023, 3:16am

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