[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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s-CONGESTION@macro-dialout-trunk:1] Set("PJSIP/398-00000625", "RC=34") in new stack	
53594	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [s-CONGESTION@macro-dialout-trunk: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 [34@macro-dialout-trunk: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 [continue@macro-dialout-trunk: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 [continue@macro-dialout-trunk: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 [9999@from-internal:13] Macro("PJSIP/398-00000625", "outisbusy,") in new stack	
53601	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [s@macro-outisbusy:1] Progress("PJSIP/398-00000625", "") in new stack	
53602	[2023-04-21 21:22:05] VERBOSE[13774][C-00000623] pbx.c: Executing [s@macro-outisbusy: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 [s@macro-outisbusy: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 [s@macro-outisbusy: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 [s@macro-outisbusy: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 [h@from-internal:1] Macro("PJSIP/398-00000625", "hangupcall") in new stack	
53612	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@crm-hangup: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 [s@crm-hangup: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 [s@crm-hangup: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 [s@crm-hangup: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 [s@crm-hangup:5] GotoIf("PJSIP/398-00000625", "0?return") in new stack	
53624	[2023-04-21 21:22:08] VERBOSE[13774][C-00000623] pbx.c: Executing [s@crm-hangup: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 [s@crm-hangup: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 [s@crm-hangup: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 [9999@from-internal: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 [s@macro-user-callerid: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 [s@macro-user-callerid:2] Set("PJSIP/398-0000066a", "CHANCONTEXT=") in new stack	
15677	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid:3] Progress("PJSIP/398-0000066a", "") in new stack	
15678	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid:4] Set("PJSIP/398-0000066a", "CHANCONTEXT=") in new stack	
15679	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:8] Set("PJSIP/398-0000066a", "AMPUSER=398") in new stack	
15683	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:10] Set("PJSIP/398-0000066a", "HOTDESKEXTEN=398") in new stack	
15685	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid:11] Set("PJSIP/398-0000066a", "HOTDESKCALL=0") in new stack	
15686	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:14] GotoIf("PJSIP/398-0000066a", "0?report") in new stack	
15689	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:16] Set("PJSIP/398-0000066a", "AMPUSER=398") in new stack	
15691	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("PJSIP/398-0000066a", "0?limit") in new stack	
15692	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid:18] Set("PJSIP/398-0000066a", "AMPUSERCIDNAME=Test") in new stack	
15693	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid:20] GotoIf("PJSIP/398-0000066a", "0?report") in new stack	
15695	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid:21] Set("PJSIP/398-0000066a", "AMPUSERCID=398") in new stack	
15696	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:26] GotoIf("PJSIP/398-0000066a", "0?limit") in new stack	
15701	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid:52] GotoIf("PJSIP/398-0000066a", "0?cnum") in new stack	
15711	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-user-callerid: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 [s@macro-user-callerid: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 [s@macro-user-callerid: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 [9999@from-internal: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 [s@sub-record-check:1] GotoIf("PJSIP/398-0000066a", "0?initialized") in new stack	
15716	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@sub-record-check: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 [s@sub-record-check:3] Set("PJSIP/398-0000066a", "NOW=1682125459") in new stack	
15718	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/398-0000066a", "__DAY=22") in new stack	
15719	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/398-0000066a", "__MONTH=04") in new stack	
15720	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/398-0000066a", "__YEAR=2023") in new stack	
15721	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@sub-record-check: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 [s@sub-record-check:8] Set("PJSIP/398-0000066a", "__FROMEXTEN=398") in new stack	
15723	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@sub-record-check: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 [s@sub-record-check:10] NoOp("PJSIP/398-0000066a", "Recordings initialized") in new stack	
15725	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [s@sub-record-check: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 [out@sub-record-check: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 [out@sub-record-check:2] Set("PJSIP/398-0000066a", "RECMODE=dontcare") in new stack	
15734	[2023-04-22 09:04:19] VERBOSE[22282][C-00000667] pbx.c: Executing [out@sub-record-check: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 [out@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check: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 [recordcheck@sub-record-check:29] Return("PJSIP/398-0000066a", "") in new stack	
15747	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [out@sub-record-check:8] Return("PJSIP/398-0000066a", "") in new stack	
15748	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [9999@from-internal: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 [9999@from-internal:4] Set("PJSIP/398-0000066a", "_ROUTEID=2") in new stack	
15750	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [9999@from-internal: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 [9999@from-internal:6] Set("PJSIP/398-0000066a", "MOHCLASS=default") in new stack	
15752	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [9999@from-internal: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 [9999@from-internal:8] Set("PJSIP/398-0000066a", "_CALLERIDNAMEINTERNAL=Test") in new stack	
15754	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [9999@from-internal:9] Set("PJSIP/398-0000066a", "_CALLERIDNUMINTERNAL=398") in new stack	
15755	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [9999@from-internal:10] Set("PJSIP/398-0000066a", "_EMAILNOTIFICATION=FALSE") in new stack	
15756	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [9999@from-internal:11] Set("PJSIP/398-0000066a", "_NODEST=") in new stack	
15757	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [9999@from-internal: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:10] GotoIf("PJSIP/398-0000066a", "0?nomax") in new stack	
15768	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-dialout-trunk:11] GotoIf("PJSIP/398-0000066a", "0?chanfull") in new stack	
15769	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-dialout-trunk:12] GotoIf("PJSIP/398-0000066a", "0?skipoutcid") in new stack	
15770	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-dialout-trunk: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 [s@macro-outbound-callerid:1] NoOp("PJSIP/398-0000066a", "398") in new stack	
15772	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outbound-callerid:2] NoOp("PJSIP/398-0000066a", "") in new stack	
15773	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outbound-callerid:3] NoOp("PJSIP/398-0000066a", "off") in new stack	
15774	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid:7] Set("PJSIP/398-0000066a", "HOTDESKEXTEN=398") in new stack	
15778	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outbound-callerid:8] Set("PJSIP/398-0000066a", "HOTDESKCALL=0") in new stack	
15779	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid:11] Set("PJSIP/398-0000066a", "ALLOWTHISROUTE=NO") in new stack	
15782	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outbound-callerid: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 [s@macro-outbound-callerid:13] ExecIf("PJSIP/398-0000066a", "0?Hangup()") in new stack	
15784	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid:20] Set("PJSIP/398-0000066a", "USEROUTCID=") in new stack	
15789	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outbound-callerid:21] Set("PJSIP/398-0000066a", "EMERGENCYCID=") in new stack	
15790	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid:26] Set("PJSIP/398-0000066a", "TRUNKOUTCID=hidden") in new stack	
15795	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid:38] Set("PJSIP/398-0000066a", "TIOHIDE=no") in new stack	
15803	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-outbound-callerid: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:15] Set("PJSIP/398-0000066a", "OUTNUM=999") in new stack	
15811	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk-predial-hook:1] MacroExit("PJSIP/398-0000066a", "") in new stack	
15818	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-dialout-trunk:22] GotoIf("PJSIP/398-0000066a", "0?skipcrm") in new stack	
15819	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:28] NoOp("PJSIP/398-0000066a", "CRM Finished") in new stack	
15826	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk:33] GotoIf("PJSIP/398-0000066a", "0?customtrunk") in new stack	
15831	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s@func-apply-sipheaders: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 [s@func-apply-sipheaders: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 [s@func-apply-sipheaders: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 [s@func-apply-sipheaders: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 [s@func-apply-sipheaders:5] While("SIP/f-pstn-0000006e", "1") in new stack	
15842	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@func-apply-sipheaders: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 [s@func-apply-sipheaders: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 [s@func-apply-sipheaders: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 [s@func-apply-sipheaders: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 [s@func-apply-sipheaders: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 [s@func-apply-sipheaders: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 [s@func-apply-sipheaders: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 [s@func-apply-sipheaders:13] EndWhile("SIP/f-pstn-0000006e", "") in new stack	
15850	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@func-apply-sipheaders:5] While("SIP/f-pstn-0000006e", "0") in new stack	
15851	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@func-apply-sipheaders: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 [s@macro-dialout-trunk: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 [s@macro-dialout-trunk: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 [s-CONGESTION@macro-dialout-trunk:1] Set("PJSIP/398-0000066a", "RC=34") in new stack	
15931	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s-CONGESTION@macro-dialout-trunk: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 [34@macro-dialout-trunk: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 [continue@macro-dialout-trunk: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 [continue@macro-dialout-trunk: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 [9999@from-internal:13] Macro("PJSIP/398-0000066a", "outisbusy,") in new stack	
15938	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outisbusy:1] Progress("PJSIP/398-0000066a", "") in new stack	
15939	[2023-04-22 09:04:20] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-outisbusy: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 [s@macro-outisbusy: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 [s@macro-outisbusy: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 [s@macro-outisbusy: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 [h@from-internal:1] Macro("PJSIP/398-0000066a", "hangupcall") in new stack	
15949	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@macro-hangupcall: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 [s@crm-hangup: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 [s@crm-hangup: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 [s@crm-hangup: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 [s@crm-hangup: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 [s@crm-hangup:5] GotoIf("PJSIP/398-0000066a", "0?return") in new stack	
15961	[2023-04-22 09:04:23] VERBOSE[22282][C-00000667] pbx.c: Executing [s@crm-hangup: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 [s@crm-hangup: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 [s@crm-hangup: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.