CallingCredit outbound calls hang up after 30seconds

retrospec · 2020-10-04 19:29:43 UTC

I’ve set up freepbx with CallingCredit trunk for outbound calls.
When i connect to my freepbx from the same local network, all outbound calls through callingcredit are handled nicely.
But when i connect to my freepbx through LTE/4G or external Wifi network, all outbound calls work fine
but they terminate after 30seconds exactly.

What amI missing?

cynjut · 2020-10-05 19:20:28 UTC

The error from the /var/log/asterisk/full log file?

This is usually a NAT error causing the router to lose confidence in your connection and terminating the stream. The log file should have the details.

You may need to turn on SIP debug as well to get the fine details of which NAT connection is giving you the problem.

retrospec · 2020-10-05 21:40:10 UTC

Ok… this is the log from the attempted call.
Using LTE/4G i placed a voice call through callingcredit from my extension 1000.
I managed to talk normally for 30 seconds and then the call terminated.
I removed all sensitive data (telephone numbers, names, etc) from the log.

I can’t find any reference to port or nat.

[2020-10-06 00:12:05] VERBOSE[28106] res_pjsip/pjsip_configuration.c: Endpoint 1000 is now Unreachable
[2020-10-06 00:12:05] VERBOSE[11062] res_pjsip/pjsip_configuration.c: Endpoint 1000 is now Reachable
[2020-10-06 00:12:05] VERBOSE[11062] res_pjsip/pjsip_options.c: Contact 1000/sip:1000@31.152.254.143:1561;rinstance=92F1263C;x-ast-orig-host=10.141.211.138:4761 is now Reachable.  RTT: 202.947 msec
[2020-10-06 00:12:16] VERBOSE[28106] pbx_variables.c: Setting global variable 'SIPDOMAIN' to 'myphone.duckdns.org'
[2020-10-06 00:12:16] VERBOSE[28106] netsock2.c: Using SIP RTP Audio TOS bits 184
[2020-10-06 00:12:16] VERBOSE[28106] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.
[2020-10-06 00:12:16] VERBOSE[28106] netsock2.c: Using SIP RTP Audio CoS mark 5
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [xxxxxxxxxx@from-internal:1] Macro("PJSIP/1000-00000014", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/1000-00000014", "TOUCH_MONITOR=1601932336.32") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/1000-00000014", "AMPUSER=1000") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:3] Set("PJSIP/1000-00000014", "HOTDESCKCHAN=1000-00000014") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:4] Set("PJSIP/1000-00000014", "HOTDESKEXTEN=1000") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/1000-00000014", "HOTDESKCALL=0") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:6] ExecIf("PJSIP/1000-00000014", "0?Set(HOTDESKCALL=1)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:7] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERID(name)=)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("PJSIP/1000-00000014", "0?report") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:9] ExecIf("PJSIP/1000-00000014", "1?Set(REALCALLERIDNUM=1000)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/1000-00000014", "AMPUSER=1000") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:11] GotoIf("PJSIP/1000-00000014", "0?limit") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:12] Set("PJSIP/1000-00000014", "AMPUSERCIDNAME=Home") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("PJSIP/1000-00000014", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:14] GotoIf("PJSIP/1000-00000014", "0?report") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:15] Set("PJSIP/1000-00000014", "AMPUSERCID=1000") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:16] Set("PJSIP/1000-00000014", "__DIAL_OPTIONS=HhTtr") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:17] Set("PJSIP/1000-00000014", "CALLERID(all)="Home" <1000>") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:18] ExecIf("PJSIP/1000-00000014", "0?Set(CUSDIAL=)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:19] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERID(all)="Home" <1000>)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:20] GotoIf("PJSIP/1000-00000014", "0?limit") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:21] ExecIf("PJSIP/1000-00000014", "1?Set(GROUP(concurrency_limit)=1000)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:22] NoOp("PJSIP/1000-00000014", "Macro Depth is 1") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:23] GotoIf("PJSIP/1000-00000014", "1?report2:macroerror") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx_builtins.c: Goto (macro-user-callerid,s,24)
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:24] GotoIf("PJSIP/1000-00000014", "1?continue") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx_builtins.c: Goto (macro-user-callerid,s,42)
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:42] Set("PJSIP/1000-00000014", "CALLERID(number)=1000") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:43] Set("PJSIP/1000-00000014", "CALLERID(name)=Home") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:44] GotoIf("PJSIP/1000-00000014", "0?cnum") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:45] Set("PJSIP/1000-00000014", "CDR(cnam)=Home") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:46] Set("PJSIP/1000-00000014", "CDR(cnum)=1000") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-user-callerid:47] Set("PJSIP/1000-00000014", "CHANNEL(language)=gr") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [xxxxxxxxxx@from-internal:2] Gosub("PJSIP/1000-00000014", "sub-record-check,s,1(out,xxxxxxxxxx,dontcare)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/1000-00000014", "0?initialized") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/1000-00000014", "__REC_STATUS=INITIALIZED") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/1000-00000014", "NOW=1601932336") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/1000-00000014", "__DAY=06") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/1000-00000014", "__MONTH=10") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/1000-00000014", "__YEAR=2020") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/1000-00000014", "__TIMESTR=20201006-001216") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/1000-00000014", "__FROMEXTEN=1000") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/1000-00000014", "__MON_FMT=wav") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/1000-00000014", "Recordings initialized") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/1000-00000014", "0?Set(ARG3=dontcare)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/1000-00000014", "REC_POLICY_MODE_SAVE=") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/1000-00000014", "0?Set(REC_STATUS=NO)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/1000-00000014", "3?checkaction") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx_builtins.c: Goto (sub-record-check,s,17)
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/1000-00000014", "1?sub-record-check,out,1") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx_builtins.c: Goto (sub-record-check,out,1)
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [out@sub-record-check:1] NoOp("PJSIP/1000-00000014", "Outbound Recording Check from 1000 to xxxxxxxxxx") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [out@sub-record-check:2] Set("PJSIP/1000-00000014", "RECMODE=dontcare") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [out@sub-record-check:3] ExecIf("PJSIP/1000-00000014", "1?Goto(routewins)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx_builtins.c: Goto (sub-record-check,out,7)
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [out@sub-record-check:7] Gosub("PJSIP/1000-00000014", "recordcheck,1(dontcare,out,xxxxxxxxxx)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/1000-00000014", "Starting recording check against dontcare") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/1000-00000014", "dontcare") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/1000-00000014", "") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [out@sub-record-check:8] Return("PJSIP/1000-00000014", "") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [xxxx@from-internal:3] Set("PJSIP/1000-00000014", "_ROUTEID=2") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [xxxx@from-internal:4] Set("PJSIP/1000-00000014", "_ROUTENAME=CallingCredit") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [xxxx@from-internal:5] Set("PJSIP/1000-00000014", "MOHCLASS=default") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [xxxx@from-internal:6] Set("PJSIP/1000-00000014", "_CALLERIDNAMEINTERNAL=Home") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [xxxx@from-internal:7] Set("PJSIP/1000-00000014", "_CALLERIDNUMINTERNAL=1000") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [xxxx@from-internal:8] Set("PJSIP/1000-00000014", "_EMAILNOTIFICATION=FALSE") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [xxxx@from-internal:9] Set("PJSIP/1000-00000014", "_NODEST=") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [xxxx@from-internal:10] Macro("PJSIP/1000-00000014", "dialout-trunk,1,xxxx,,off") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:1] Set("PJSIP/1000-00000014", "DIAL_TRUNK=1") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:2] ExecIf("PJSIP/1000-00000014", "0?Set(DIAL_OPTIONS=Hhtr)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:3] GosubIf("PJSIP/1000-00000014", "0?sub-pincheck,s,1()") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:4] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERID(num)=1000)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:5] GotoIf("PJSIP/1000-00000014", "0?disabletrunk,1") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:6] Set("PJSIP/1000-00000014", "DIAL_NUMBER=xxxx") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:7] Set("PJSIP/1000-00000014", "DIAL_TRUNK_OPTIONS=HhTtr") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:8] Set("PJSIP/1000-00000014", "OUTBOUND_GROUP=OUT_1") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:9] Set("PJSIP/1000-00000014", "DIAL_TRUNK_OPTIONS=T") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:10] GotoIf("PJSIP/1000-00000014", "0?nomax") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:11] GotoIf("PJSIP/1000-00000014", "0?chanfull") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:12] GotoIf("PJSIP/1000-00000014", "0?skipoutcid") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:13] Macro("PJSIP/1000-00000014", "outbound-callerid,1") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:1] NoOp("PJSIP/1000-00000014", "1000") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:2] NoOp("PJSIP/1000-00000014", "") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:3] NoOp("PJSIP/1000-00000014", "off") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERPRES(name-pres)=)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:5] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERPRES(num-pres)=)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:6] Set("PJSIP/1000-00000014", "HOTDESCKCHAN=1000-00000014") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:7] Set("PJSIP/1000-00000014", "HOTDESKEXTEN=1000") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:8] Set("PJSIP/1000-00000014", "HOTDESKCALL=0") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:9] ExecIf("PJSIP/1000-00000014", "0?Set(HOTDESKCALL=1)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:10] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERID(name)=)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:11] Set("PJSIP/1000-00000014", "ALLOWTHISROUTE=NO") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:12] ExecIf("PJSIP/1000-00000014", "0?Set(ALLOWTHISROUTE=YES)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:13] ExecIf("PJSIP/1000-00000014", "0?Hangup()") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:14] ExecIf("PJSIP/1000-00000014", "0?Set(REALCALLERIDNUM=1000)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:15] ExecIf("PJSIP/1000-00000014", "0?Set(AMPUSER=1000)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:16] GotoIf("PJSIP/1000-00000014", "1?normcid") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx_builtins.c: Goto (macro-outbound-callerid,s,20)
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:20] Set("PJSIP/1000-00000014", "USEROUTCID=") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:21] Set("PJSIP/1000-00000014", "EMERGENCYCID=") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf("PJSIP/1000-00000014", "0?Set(EMERGENCYCID=)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:23] Set("PJSIP/1000-00000014", "TRUNKOUTCID=<+30xxxxxxxx>") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:24] GotoIf("PJSIP/1000-00000014", "1?trunkcid") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx_builtins.c: Goto (macro-outbound-callerid,s,30)
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:30] ExecIf("PJSIP/1000-00000014", "1?Set(CALLERID(all)=<+30xxxxxxxxxxx>)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:31] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERID(all)=)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:32] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERID(all)=)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:33] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERID(all)=1000)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:34] Set("PJSIP/1000-00000014", "TIOHIDE=no") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:35] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:36] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:37] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:38] ExecIf("PJSIP/1000-00000014", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:39] Set("PJSIP/1000-00000014", "CDR(outbound_cnum)=+30xxxxxxxxx") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-outbound-callerid:40] Set("PJSIP/1000-00000014", "CDR(outbound_cnam)=") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:14] GosubIf("PJSIP/1000-00000014", "1?sub-flp-1,s,1()") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-flp-1:1] ExecIf("PJSIP/1000-00000014", "0?Set(TARGET_FLP_1=0030xxxxxxx)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-flp-1:2] GotoIf("PJSIP/1000-00000014", "0?match") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-flp-1:3] ExecIf("PJSIP/1000-00000014", "1?Set(TARGET_FLP_1=0030xxxxxxx)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-flp-1:4] GotoIf("PJSIP/1000-00000014", "1?match") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx_builtins.c: Goto (sub-flp-1,s,6)
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-flp-1:6] Set("PJSIP/1000-00000014", "DIAL_NUMBER=0030xxxxxxxxx") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@sub-flp-1:7] Return("PJSIP/1000-00000014", "") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:15] Set("PJSIP/1000-00000014", "OUTNUM=0030xxxxxxxxx") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:16] Set("PJSIP/1000-00000014", "custom=PJSIP") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf("PJSIP/1000-00000014", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:18] ExecIf("PJSIP/1000-00000014", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:19] Macro("PJSIP/1000-00000014", "dialout-trunk-predial-hook,") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("PJSIP/1000-00000014", "") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:20] GotoIf("PJSIP/1000-00000014", "0?bypass,1") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:21] ExecIf("PJSIP/1000-00000014", "1?Set(CONNECTEDLINE(num,i)=0030xxxxxxxxxxx)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:22] ExecIf("PJSIP/1000-00000014", "1?Set(CONNECTEDLINE(name,i)=CID:+30xxxxxxxxx)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:23] ExecIf("PJSIP/1000-00000014", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)+30xxxxxxxxxx)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:24] GotoIf("PJSIP/1000-00000014", "0?customtrunk") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:25] ExecIf("PJSIP/1000-00000014", "0?Set(DIAL_TRUNK_OPTIONS=)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:26] Set("PJSIP/1000-00000014", "HASH(__SIPHEADERS,Alert-Info)=unset") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-dialout-trunk:27] Dial("PJSIP/1000-00000014", "PJSIP/0030xxxxxxxxxx@CallingCredit,300,Tb(func-apply-sipheaders^s^1,(1))") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] app_stack.c: PJSIP/CallingCredit-00000015 Internal Gosub(func-apply-sipheaders,s,1(1)) start
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("PJSIP/CallingCredit-00000015", "Applying SIP Headers to channel PJSIP/CallingCredit-00000015") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:2] Set("PJSIP/CallingCredit-00000015", "TECH=PJSIP") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/CallingCredit-00000015", "SIPHEADERKEYS=Alert-Info") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:4] While("PJSIP/CallingCredit-00000015", "1") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:5] Set("PJSIP/CallingCredit-00000015", "sipheader=unset") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:6] ExecIf("PJSIP/CallingCredit-00000015", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:7] ExecIf("PJSIP/CallingCredit-00000015", "1?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2020-10-06 00:12:16] ERROR[4157] res_pjsip_header_funcs.c: No headers had been previously added to this session.
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:8] ExecIf("PJSIP/CallingCredit-00000015", "0?Set(sipheader=<http://127.0.0.1>;info=unset)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("PJSIP/CallingCredit-00000015", "0?Set(sipheader=<http://127.0.0.1>unset)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("PJSIP/CallingCredit-00000015", "0?SIPAddHeader(Alert-Info:unset)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("PJSIP/CallingCredit-00000015", "0?Set(PJSIP_HEADER(add,Alert-Info)=unset)") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:12] EndWhile("PJSIP/CallingCredit-00000015", "") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:4] While("PJSIP/CallingCredit-00000015", "0") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] pbx.c: Executing [s@func-apply-sipheaders:13] Return("PJSIP/CallingCredit-00000015", "") in new stack
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] app_stack.c: Spawn extension (from-pstn, xxxxxxxxx, 1) exited non-zero on 'PJSIP/CallingCredit-00000015'
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] app_stack.c: PJSIP/CallingCredit-00000015 Internal Gosub(func-apply-sipheaders,s,1(1)) complete GOSUB_RETVAL=
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] app_dial.c: Called PJSIP/0030xxxxxxxxxxx@CallingCredit
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] app_dial.c: PJSIP/CallingCredit-00000015 is making progress passing it to PJSIP/1000-00000014
[2020-10-06 00:12:16] VERBOSE[910][C-0000000e] app_dial.c: PJSIP/CallingCredit-00000015 is making progress passing it to PJSIP/1000-00000014
[2020-10-06 00:12:27] VERBOSE[910][C-0000000e] app_dial.c: PJSIP/CallingCredit-00000015 answered PJSIP/1000-00000014
[2020-10-06 00:12:27] VERBOSE[928][C-0000000e] bridge_channel.c: Channel PJSIP/CallingCredit-00000015 joined 'simple_bridge' basic-bridge <dbec3a7f-af8c-4cde-9dc8-30811d758ad6>
[2020-10-06 00:12:27] VERBOSE[910][C-0000000e] bridge_channel.c: Channel PJSIP/1000-00000014 joined 'simple_bridge' basic-bridge <dbec3a7f-af8c-4cde-9dc8-30811d758ad6>
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] bridge_channel.c: Channel PJSIP/1000-00000014 left 'simple_bridge' basic-bridge <dbec3a7f-af8c-4cde-9dc8-30811d758ad6>
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] app_macro.c: Spawn extension (macro-dialout-trunk, s, 27) exited non-zero on 'PJSIP/1000-00000014' in macro 'dialout-trunk'
[2020-10-06 00:12:59] VERBOSE[928][C-0000000e] bridge_channel.c: Channel PJSIP/CallingCredit-00000015 left 'simple_bridge' basic-bridge <dbec3a7f-af8c-4cde-9dc8-30811d758ad6>
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] pbx.c: Spawn extension (from-internal, xxxxxxxx, 10) exited non-zero on 'PJSIP/1000-00000014'
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] pbx.c: Executing [h@from-internal:1] Macro("PJSIP/1000-00000014", "hangupcall") in new stack
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/1000-00000014", "1?theend") in new stack
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/1000-00000014", "0?Set(CDR(recordingfile)=)") in new stack
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-hangupcall:4] NoOp("PJSIP/1000-00000014", "PJSIP/CallingCredit-00000015 montior file= ") in new stack
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-hangupcall:5] GotoIf("PJSIP/1000-00000014", "1?skipagi") in new stack
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] pbx_builtins.c: Goto (macro-hangupcall,s,7)
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] pbx.c: Executing [s@macro-hangupcall:7] Hangup("PJSIP/1000-00000014", "") in new stack
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] app_macro.c: Spawn extension (macro-hangupcall, s, 7) exited non-zero on 'PJSIP/1000-00000014' in macro 'hangupcall'
[2020-10-06 00:12:59] VERBOSE[910][C-0000000e] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/1000-00000014'
[2020-10-06 00:13:36] VERBOSE[4157] res_pjsip_registrar.c: Removed contact 'sip:1000@31.152.254.143:1561;rinstance=92F1263C;x-ast-orig-host=10.141.211.138:4761' from AOR '1000' due to request
[2020-10-06 00:13:36] VERBOSE[11062] res_pjsip/pjsip_options.c: Contact 1000/sip:1000@31.152.254.143:1561;rinstance=92F1263C;x-ast-orig-host=10.141.211.138:4761 has been deleted

Stewart1 · 2020-10-06 04:04:21 UTC

Do calls from external extension 1000 to internal extensions or internal services such as *43 (echo test) also drop after 30 seconds? If not, try setting Direct Media to No for both extension and trunk. If no luck, post a SIP trace as noted below.

If all calls from external extensions fail, confirm that you are not forwarding the external SIP port to a different internal port, and that in Asterisk SIP Settings, External Address and Local Networks are correctly set.

If you still have trouble, at the Asterisk command prompt, type
pjsip set logger on
make a failing test call, post the Asterisk log for the call at pastebin.freepbx.org and post the link here.

Also, what router/firewall are you using for the PBX? Any special settings?

retrospec · 2020-10-06 10:59:54 UTC

I made a call from my Phone (ext 1000) external network 4G to my iMac (ext 1003) local network.
Call lasted for 30seconds and then terminated
https://pastebin.freepbx.org/view/a2dcf17f

When I place the call from my iMac to my Phone (local to wan) it works fine.
The issue is when the call is initiated from wan to lan (whether it is to an extension, outbound call or *43).

My router is amplifi HD (ubiquiti)
I have forwarded the RTP port range 10000-10100 to the local ip of the freepbx.
Also the port 8765 to 5060 and softphone connects to xxxx.duckdns.net:8765

What else needs to be done?
Thank you.

Stewart1 · 2020-10-06 15:40:00 UTC

That’s your problem. Asterisk knows that it’s listening on 5060 and also knows that its public IP is what xxxx.duckdns.net resolves to. So when it responds to extension 1000’s INVITE with a 200 OK, the Contact header is effectively xxxx.duckdns.net:5060, the phone sends the ACK there, it never arrives and the call drops.

The simple fix: In Asterisk SIP Settings, chan_pjsip tab, change Port to Listen On from 5060 to 8765 and restart Asterisk. In the router, change the forwarding to 8765 -> 8765. Unfortunately, you will have to change all your internal extensions to register to port 8765.

It’s technically possible to have different external and internal SIP ports, but there are some subtle issues and I don’t recommend it.

Using the standard range of 10000-20000 is somewhat more secure.

BTW, your log did not contain a SIP trace. To provide one in the future, confirm that you see
PJSIP Logging enabled
when you turn logging on, and don’t change any settings (reload turns logging off) from then until you have made your test call.

retrospec · 2020-10-06 15:43:43 UTC

that was it. Thank you!
I changed the default udp port in chan_pjsip tab to 8765,
forwarded 8765 to 8765 (and not 5060) , restart asterisk and problem solved.

All my extensions were registered to xxx.duckdns.org:8765 in the first place, even the ones that are fixed in the local network, so it wasnt a mess.

retrospec · 2020-10-06 15:57:34 UTC

If you still have trouble, at the Asterisk command prompt, type
pjsip set logger on

fwconsole pjsip set logger on

responds with:

Command ‘pjsip’ is not defined.
Did you mean this?
convert2pjsip

Stewart1 · 2020-10-06 16:19:46 UTC

pjsip set logger on is an Asterisk command, given at the Asterisk command prompt.
You can do this by running
asterisk -r
from a root shell prompt, or in the GUI at Admin -> Asterisk CLI

system · 2020-10-13 16:19:48 UTC

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