All SIP phone calls drop after 32 seconds exactly

FreePBX
1

PBX Firmware:
12.7.5-1902-1.sng7
PBX Service Pack:
1.0.0.0

Current Asterisk Version: 13.22.0
FreePBX 14.0.5.25

Outbound calls this morning suddenly started dropping after 30 seconds on our Sangoma S500’s PJSIP configured extensions.

Incoming calls not affected.

Outgoing calls from an analogue phone to FXO unaffected.

here is a log of failed call;

[2019-02-06 14:54:39] VERBOSE[4643][C-00000008] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on ‘PJSIP/3160-00000003’
[2019-02-06 15:00:31] VERBOSE[4314] asterisk.c: Remote UNIX connection disconnected
[2019-02-06 15:01:12] VERBOSE[2216] pbx_variables.c: Setting global variable ‘SIPDOMAIN’ to ‘192.168.n.nnn’
[2019-02-06 15:01:12] VERBOSE[2216] netsock2.c: Using SIP RTP Audio TOS bits 184
[2019-02-06 15:01:12] VERBOSE[2216] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.
[2019-02-06 15:01:12] VERBOSE[2216] netsock2.c: Using SIP RTP Audio CoS mark 5
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [2508nnnnnn@from-internal:1] Macro(“PJSIP/3160-00000004”, “user-callerid,LIMIT,EXTERNAL,”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:1] Set(“PJSIP/3160-00000004”, “TOUCH_MONITOR=1549494072.20”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:2] Set(“PJSIP/3160-00000004”, “AMPUSER=3160”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:3] GotoIf(“PJSIP/3160-00000004”, “0?report”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:4] ExecIf(“PJSIP/3160-00000004”, “1?Set(REALCALLERIDNUM=3160)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:5] Set(“PJSIP/3160-00000004”, “AMPUSER=3160”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:6] GotoIf(“PJSIP/3160-00000004”, “0?limit”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:7] Set(“PJSIP/3160-00000004”, “AMPUSERCIDNAME=Edwin”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:8] ExecIf(“PJSIP/3160-00000004”, “0?Set(__CIDMASQUERADING=TRUE)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:9] GotoIf(“PJSIP/3160-00000004”, “0?report”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:10] Set(“PJSIP/3160-00000004”, “AMPUSERCID=3160”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:11] Set(“PJSIP/3160-00000004”, “__DIAL_OPTIONS=Ttr”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:12] Set(“PJSIP/3160-00000004”, “CALLERID(all)=“Edwin” <3160>”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:13] GotoIf(“PJSIP/3160-00000004”, “0?limit”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:14] ExecIf(“PJSIP/3160-00000004”, “1?Set(GROUP(concurrency_limit)=3160)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:15] ExecIf(“PJSIP/3160-00000004”, “0?Set(CHANNEL(language)=)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:16] NoOp(“PJSIP/3160-00000004”, “Macro Depth is 1”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:17] GotoIf(“PJSIP/3160-00000004”, “1?report2:macroerror”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:18] GotoIf(“PJSIP/3160-00000004”, “1?continue”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:37] Set(“PJSIP/3160-00000004”, “CALLERID(number)=3160”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:38] Set(“PJSIP/3160-00000004”, “CALLERID(name)=Edwin”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:39] GotoIf(“PJSIP/3160-00000004”, “0?cnum”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:40] Set(“PJSIP/3160-00000004”, “CDR(cnam)=Edwin”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:41] Set(“PJSIP/3160-00000004”, “CDR(cnum)=3160”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-user-callerid:42] Set(“PJSIP/3160-00000004”, “CHANNEL(language)=en”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [2508nnnnnn@from-internal:2] Gosub(“PJSIP/3160-00000004”, “sub-record-check,s,1(out,2508nnnnnn,dontcare)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:1] GotoIf(“PJSIP/3160-00000004”, “0?initialized”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:2] Set(“PJSIP/3160-00000004”, “__REC_STATUS=INITIALIZED”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:3] Set(“PJSIP/3160-00000004”, “NOW=1549494072”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:4] Set(“PJSIP/3160-00000004”, “__DAY=06”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:5] Set(“PJSIP/3160-00000004”, “__MONTH=02”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:6] Set(“PJSIP/3160-00000004”, “__YEAR=2019”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:7] Set(“PJSIP/3160-00000004”, “__TIMESTR=20190206-150112”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:8] Set(“PJSIP/3160-00000004”, “__FROMEXTEN=3160”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:9] Set(“PJSIP/3160-00000004”, “__MON_FMT=wav”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:10] NoOp(“PJSIP/3160-00000004”, “Recordings initialized”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:11] ExecIf(“PJSIP/3160-00000004”, “0?Set(ARG3=dontcare)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:12] Set(“PJSIP/3160-00000004”, “REC_POLICY_MODE_SAVE=”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:13] ExecIf(“PJSIP/3160-00000004”, “0?Set(REC_STATUS=NO)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:14] GotoIf(“PJSIP/3160-00000004”, “3?checkaction”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@sub-record-check:17] GotoIf(“PJSIP/3160-00000004”, “1?sub-record-check,out,1”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx_builtins.c: Goto (sub-record-check,out,1)
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [out@sub-record-check:1] NoOp(“PJSIP/3160-00000004”, “Outbound Recording Check from 3160 to 2508nnnnnn”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [out@sub-record-check:2] Set(“PJSIP/3160-00000004”, “RECMODE=dontcare”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [out@sub-record-check:3] ExecIf(“PJSIP/3160-00000004”, “1?Goto(routewins)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx_builtins.c: Goto (sub-record-check,out,7)
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [out@sub-record-check:7] Gosub(“PJSIP/3160-00000004”, “recordcheck,1(dontcare,out,2508nnnnnn)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“PJSIP/3160-00000004”, “Starting recording check against dontcare”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“PJSIP/3160-00000004”, “dontcare”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“PJSIP/3160-00000004”, “”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [out@sub-record-check:8] Return(“PJSIP/3160-00000004”, “”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [2508nnnnnn@from-internal:3] ExecIf(“PJSIP/3160-00000004”, “0 ?Set(CDR(accountcode)=)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [2508nnnnnn@from-internal:4] Set(“PJSIP/3160-00000004”, “MOHCLASS=default”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [2508nnnnnn@from-internal:5] ExecIf(“PJSIP/3160-00000004”, “1?Set(TRUNKCIDOVERRIDE=2503nnnnnn)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [2508nnnnnn@from-internal:6] Set(“PJSIP/3160-00000004”, “_NODEST=”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [2508nnnnnn@from-internal:7] Macro(“PJSIP/3160-00000004”, “dialout-trunk,1,12508nnnnnn,on”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:1] Set(“PJSIP/3160-00000004”, “DIAL_TRUNK=1”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:2] ExecIf(“PJSIP/3160-00000004”, “0?Set(DIAL_OPTIONS=tr)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:3] GosubIf(“PJSIP/3160-00000004”, “0?sub-pincheck,s,1()”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:4] ExecIf(“PJSIP/3160-00000004”, “0?Set(CALLERID(num)=3160)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:5] GotoIf(“PJSIP/3160-00000004”, “0?disabletrunk,1”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:6] Set(“PJSIP/3160-00000004”, “DIAL_NUMBER=12508nnnnnn”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:7] Set(“PJSIP/3160-00000004”, “DIAL_TRUNK_OPTIONS=Ttr”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:8] Set(“PJSIP/3160-00000004”, “OUTBOUND_GROUP=OUT_1”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:9] Set(“PJSIP/3160-00000004”, “DIAL_TRUNK_OPTIONS=T”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:10] GotoIf(“PJSIP/3160-00000004”, “1?nomax”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx_builtins.c: Goto (macro-dialout-trunk,s,12)
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:12] GotoIf(“PJSIP/3160-00000004”, “0?skipoutcid”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:13] Macro(“PJSIP/3160-00000004”, “outbound-callerid,1”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:1] NoOp(“PJSIP/3160-00000004”, “3160”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:2] NoOp(“PJSIP/3160-00000004”, “”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:3] NoOp(“PJSIP/3160-00000004”, “off”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf(“PJSIP/3160-00000004”, “0?Set(CALLERPRES(name-pres)=)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:5] ExecIf(“PJSIP/3160-00000004”, “0?Set(CALLERPRES(num-pres)=)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:6] ExecIf(“PJSIP/3160-00000004”, “0?Set(REALCALLERIDNUM=3160)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:7] ExecIf(“PJSIP/3160-00000004”, “0?Set(AMPUSER=3160)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:8] GotoIf(“PJSIP/3160-00000004”, “1?normcid”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx_builtins.c: Goto (macro-outbound-callerid,s,12)
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:12] Set(“PJSIP/3160-00000004”, “USEROUTCID=”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:13] Set(“PJSIP/3160-00000004”, “EMERGENCYCID=”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:14] Set(“PJSIP/3160-00000004”, “TRUNKOUTCID=<2503nnnnnn>”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:15] GotoIf(“PJSIP/3160-00000004”, “1?trunkcid”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx_builtins.c: Goto (macro-outbound-callerid,s,20)
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:20] ExecIf(“PJSIP/3160-00000004”, “1?Set(CALLERID(all)=<2503nnnnnn>)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:21] ExecIf(“PJSIP/3160-00000004”, “0?Set(CALLERID(all)=)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf(“PJSIP/3160-00000004”, “1?Set(CALLERID(all)=2503nnnnnn)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:23] ExecIf(“PJSIP/3160-00000004”, “0?Set(CALLERPRES(name-pres)=prohib_passed_screen)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:24] ExecIf(“PJSIP/3160-00000004”, “0?Set(CALLERPRES(num-pres)=prohib_passed_screen)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:25] Set(“PJSIP/3160-00000004”, “CDR(outbound_cnum)=2503nnnnnn”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-outbound-callerid:26] Set(“PJSIP/3160-00000004”, “CDR(outbound_cnam)=”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:14] GosubIf(“PJSIP/3160-00000004”, “0?sub-flp-1,s,1()”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:15] Set(“PJSIP/3160-00000004”, “OUTNUM=12508nnnnnn”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:16] Set(“PJSIP/3160-00000004”, “custom=DAHDI/G0”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf(“PJSIP/3160-00000004”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:18] ExecIf(“PJSIP/3160-00000004”, “0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:19] Macro(“PJSIP/3160-00000004”, “dialout-trunk-predial-hook,”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“PJSIP/3160-00000004”, “”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:20] GotoIf(“PJSIP/3160-00000004”, “0?bypass,1”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:21] ExecIf(“PJSIP/3160-00000004”, “1?Set(CONNECTEDLINE(num,i)=12508nnnnnn)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:22] ExecIf(“PJSIP/3160-00000004”, “1?Set(CONNECTEDLINE(name,i)=CID:2503nnnnnn)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:23] ExecIf(“PJSIP/3160-00000004”, “0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)2503nnnnnn)”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:24] GotoIf(“PJSIP/3160-00000004”, “0?customtrunk”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-dialout-trunk:25] Dial(“PJSIP/3160-00000004”, “DAHDI/G0/12508nnnnnn,300,Tb(func-apply-sipheaders^s^1,(1))”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] app_stack.c: DAHDI/3-1 Internal Gosub(func-apply-sipheaders,s,1(1)) start
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp(“DAHDI/3-1”, “Applying SIP Headers to channel DAHDI/3-1”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@func-apply-sipheaders:2] Set(“DAHDI/3-1”, “TECH=DAHDI”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@func-apply-sipheaders:3] Set(“DAHDI/3-1”, “SIPHEADERKEYS=”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@func-apply-sipheaders:4] While(“DAHDI/3-1”, “0”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] app_while.c: Jumping to priority 11
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] pbx.c: Executing [s@func-apply-sipheaders:12] Return(“DAHDI/3-1”, “”) in new stack
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] app_stack.c: Spawn extension (from-analog, 2508nnnnnn, 1) exited non-zero on ‘DAHDI/3-1’
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] app_stack.c: DAHDI/3-1 Internal Gosub(func-apply-sipheaders,s,1(1)) complete GOSUB_RETVAL=
[2019-02-06 15:01:12] VERBOSE[8230][C-00000009] app_dial.c: Called DAHDI/G0/12508nnnnnn
[2019-02-06 15:01:15] VERBOSE[8230][C-00000009] app_dial.c: DAHDI/3-1 answered PJSIP/3160-00000004
[2019-02-06 15:01:15] VERBOSE[8255][C-00000009] bridge_channel.c: Channel DAHDI/3-1 joined ‘simple_bridge’ basic-bridge <807ea1f6-0d93-41ca-8e4b-5cde465a6fb9>
[2019-02-06 15:01:15] VERBOSE[8230][C-00000009] bridge_channel.c: Channel PJSIP/3160-00000004 joined ‘simple_bridge’ basic-bridge <807ea1f6-0d93-41ca-8e4b-5cde465a6fb9>
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] bridge_channel.c: Channel PJSIP/3160-00000004 left ‘simple_bridge’ basic-bridge <807ea1f6-0d93-41ca-8e4b-5cde465a6fb9>
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] app_macro.c: Spawn extension (macro-dialout-trunk, s, 25) exited non-zero on ‘PJSIP/3160-00000004’ in macro ‘dialout-trunk’
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] pbx.c: Spawn extension (from-internal, 2508nnnnnn, 7) exited non-zero on ‘PJSIP/3160-00000004’
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] pbx.c: Executing [h@from-internal:1] Macro(“PJSIP/3160-00000004”, “hangupcall”) in new stack
[2019-02-06 15:01:47] VERBOSE[8255][C-00000009] bridge_channel.c: Channel DAHDI/3-1 left ‘simple_bridge’ basic-bridge <807ea1f6-0d93-41ca-8e4b-5cde465a6fb9>
[2019-02-06 15:01:47] VERBOSE[8255][C-00000009] sig_analog.c: Hanging up on ‘DAHDI/3-1’
[2019-02-06 15:01:47] VERBOSE[8255][C-00000009] chan_dahdi.c: Hungup ‘DAHDI/3-1’
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-hangupcall:1] GotoIf(“PJSIP/3160-00000004”, “1?theend”) in new stack
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-hangupcall:3] ExecIf(“PJSIP/3160-00000004”, “0?Set(CDR(recordingfile)=)”) in new stack
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-hangupcall:4] NoOp(“PJSIP/3160-00000004”, "DAHDI/3-1 montior file= ") in new stack
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-hangupcall:5] GotoIf(“PJSIP/3160-00000004”, “1?skipagi”) in new stack
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] pbx_builtins.c: Goto (macro-hangupcall,s,7)
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] pbx.c: Executing [s@macro-hangupcall:7] Hangup(“PJSIP/3160-00000004”, “”) in new stack
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] app_macro.c: Spawn extension (macro-hangupcall, s, 7) exited non-zero on ‘PJSIP/3160-00000004’ in macro ‘hangupcall’
[2019-02-06 15:01:47] VERBOSE[8230][C-00000009] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on ‘PJSIP/3160-00000004’

if looks like the S500 is initiating the hangup.

If I could get some pointers, I would be very grateful, thank you.

Further discovery after close of business… internal and external calls drop at exactly 32 seconds. My VPN phone at home has no problems with calls.

2

I’m looking at logs but nothing is obvious.

Anyone?

3

Hi.
Nat in your router/firewall the rtp ports and 5060 port to your freepbx.
But traslate only the public ip of your provider because all the traffic is very dangerous.
Many hacker scan this network ports

4

This is usually a router configuration problem and/or a NAT problem.

For whatever reason, your router is shutting down the connection at 30 seconds because a critical path update packet is closing your session.

Turn on SIP DEBUG on the system and make a call that fails.

It’s also possible that one of the other “keep alive” packets is causing the router to time your stream out. Since you are not seeing it on THIS machine’s logs, we have to assume that “the action” is happening on one of the other devices in the call stream. A SIP DEBUG should help us point to the culprit.

Look back through the archive for “30 seconds” and you will see dozens of threads just like this one. Note that it could be one of a dozen or so issues, so you may need to search around a little bit in your network to find the problem.

1 Like
5

The best way to actually see what is really happening is this:

pjsip set logger on

Make a call and paste the output here so we can see the actual SIP messages that are happening. Looking in the full log tells you how Asterisk processed the call in the dialplan. It doesn’t tell you any of the actual SIP messaging/packet information such as misconfigured SDP, etc.

2 Likes
6

Thank you everyone for your answers, I will follow up when I get into my business And paste info here.

As I have POTS lines I have the firewall locked down to external intrusion (I will triple check).

Incidentally my S500 at home on VPN works fine.

7

@BlazeStudios Thank you here is a debug.

3160 is calling 3195, FYI

I also see reference to my WAN IP yet 5060 is blocked and other than the VPN phone, everything is on my LAN.

https://pastebin.freepbx.org/view/6d6763fa

8

Yeah, that debug is pretty much unreadable because you’ve destroyed the formatting and everything is jammed into one line and impossible to read. You need to post a much cleaner version.

9

Thanks for letting me know Tom, what is the best way to capture the pjsip logger output?

10

You SSH into the server, do

asterisk -r
pjsip set logger on

Make the call, reproduce the issue. Copy and paste the output from the call.

11

Is this sufficient Tom? It captured a lot of traffic so I hope I grabbed enough for you?

Content-Length: 296

v=0
o=- 6666 5 IN IP4 192.168.0.19
s=Asterisk
c=IN IP4 192.168.0.19
t=0 0
m=audio 11356 RTP/AVP 0 8 3 2 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[2019-02-08 15:00:41] VERBOSE[5379] res_pjsip_logger.c: <— Transmitting SIP request (483 bytes) to UDP:192.168.0.58:59273 —>
OPTIONS sip:[email protected]:59273;rinstance=f13350a4f8e8b87a SIP/2.0
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport;branch=z9hG4bKPj68fe4556-cb19-4fed-b89d-7c0a3fd76c81
From: sip:[email protected];tag=0fb1151a-69d8-4a4d-911b-bac605a54ce4
To: sip:[email protected];rinstance=f13350a4f8e8b87a
Contact: sip:[email protected]:5060
Call-ID: 9d0ab605-7c3e-4820-a3e6-e320ea1cd57f
CSeq: 13165 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Length: 0

[2019-02-08 15:00:41] VERBOSE[2230] res_pjsip_logger.c: <— Received SIP response (627 bytes) from UDP:192.168.0.58:59273 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport=5060;branch=z9hG4bKPj68fe4556-cb19-4fed-b89d-7c0a3fd76c81;received=192.168.0.19
Contact: sip:192.168.0.58:59273
To: sip:[email protected];rinstance=f13350a4f8e8b87a;tag=b8a9095a
From: sip:[email protected];tag=0fb1151a-69d8-4a4d-911b-bac605a54ce4
Call-ID: 9d0ab605-7c3e-4820-a3e6-e320ea1cd57f
CSeq: 13165 OPTIONS
Accept: application/sdp
Accept-Language: en
Allow: OPTIONS, SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, MESSAGE
Supported: replaces
User-Agent: X-Lite release 5.4.0 stamp 94388
Allow-Events: talk, hold
Content-Length: 0

[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] app_dial.c: DAHDI/4-1 answered DAHDI/1-1
[2019-02-08 15:00:43] VERBOSE[9190] res_pjsip_logger.c: <— Transmitting SIP request (804 bytes) to UDP:10.8.0.17:5060 —>
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 10.8.0.1:5060;rport;branch=z9hG4bKPj0b3973b2-e52c-4479-8038-1fe82a3a42a9
From: sip:[email protected];tag=97e602fe-85ca-46f9-908e-da3c2a02c4ef
To: “E-Home” sip:[email protected];tag=1ad2846ee1c0d01
Contact: sip:10.8.0.1:5060
Call-ID: [email protected]
CSeq: 29812 NOTIFY
Event: dialog
Subscription-State: active;expires=261
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Type: application/dialog-info+xml
Content-Length: 231

<?xml version="1.0" encoding="UTF-8"?> confirmed

[2019-02-08 15:00:43] VERBOSE[9190] res_pjsip_logger.c: <— Transmitting SIP request (827 bytes) to UDP:192.168.0.62:5060 —>
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport;branch=z9hG4bKPj22c4b144-0a99-4537-a60a-2b8590f726b9
From: sip:[email protected];tag=bec3e079-b096-47d8-8ea3-76d1675ad92c
To: “Cindy” sip:[email protected];tag=779a34eea22151d
Contact: sip:my.wan.ip.addr:5060
Call-ID: [email protected]
CSeq: 19540 NOTIFY
Event: dialog
Subscription-State: active;expires=54
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Type: application/dialog-info+xml
Content-Length: 230

<?xml version="1.0" encoding="UTF-8"?> confirmed

[2019-02-08 15:00:43] VERBOSE[5379] res_pjsip_logger.c: <— Transmitting SIP request (483 bytes) to UDP:192.168.0.62:5160 —>
CANCEL sip:[email protected]:5160 SIP/2.0
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport;branch=z9hG4bKPj2f3c9dcb-8490-4dbe-9806-9d0d614bda6e
From: “Nelson, BC” sip:[email protected];tag=3ad7b6a5-8289-4142-b418-5409370b9213
To: sip:[email protected]
Call-ID: 7241848e-7247-4097-827f-5db2a3a745f3
CSeq: 14560 CANCEL
Reason: SIP;cause=200;text=“Call completed elsewhere”
Reason: Q.850;cause=26
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Length: 0

[2019-02-08 15:00:43] VERBOSE[7166] res_pjsip_logger.c: <— Transmitting SIP request (804 bytes) to UDP:10.8.0.17:5060 —>
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 10.8.0.1:5060;rport;branch=z9hG4bKPj96a4181e-6cb7-4928-88e3-91e1845307c8
From: sip:[email protected];tag=42e62f0d-3a80-4d16-b54c-20534c8d1618
To: “E-Home” sip:[email protected];tag=83810dfb64c6303
Contact: sip:10.8.0.1:5060
Call-ID: [email protected]
CSeq: 17036 NOTIFY
Event: dialog
Subscription-State: active;expires=263
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Type: application/dialog-info+xml
Content-Length: 231

<?xml version="1.0" encoding="UTF-8"?> terminated

[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] pbx.c: Executing [s@macro-auto-blkvm:1] Set(“DAHDI/4-1”, “__MACRO_RESULT=”) in new stack
[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] pbx.c: Executing [s@macro-auto-blkvm:2] Set(“DAHDI/4-1”, “CFIGNORE=”) in new stack
[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] pbx.c: Executing [s@macro-auto-blkvm:3] Set(“DAHDI/4-1”, “MASTER_CHANNEL(CFIGNORE)=”) in new stack
[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] pbx.c: Executing [s@macro-auto-blkvm:4] Set(“DAHDI/4-1”, “FORWARD_CONTEXT=from-internal”) in new stack
[2019-02-08 15:00:43] VERBOSE[2230] res_pjsip_logger.c: <— Received SIP response (483 bytes) from UDP:192.168.0.62:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport=5060;branch=z9hG4bKPj22c4b144-0a99-4537-a60a-2b8590f726b9;received=192.168.0.19
From: sip:[email protected];tag=bec3e079-b096-47d8-8ea3-76d1675ad92c
To: “Cindy” sip:[email protected];tag=779a34eea22151d
Call-ID: [email protected]
CSeq: 19540 NOTIFY
User-Agent: Sangoma S500 V2.0.4.57
Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK
Content-Length: 0

[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] pbx.c: Executing [s@macro-auto-blkvm:5] Set(“DAHDI/4-1”, “MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal”) in new stack
[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] pbx.c: Executing [s@macro-auto-blkvm:6] Macro(“DAHDI/4-1”, “blkvm-clr,”) in new stack
[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] pbx.c: Executing [s@macro-blkvm-clr:1] Set(“DAHDI/4-1”, “SHARED(BLKVM,DAHDI/1-1)=”) in new stack
[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] pbx.c: Executing [s@macro-blkvm-clr:2] Set(“DAHDI/4-1”, “GOSUB_RETVAL=”) in new stack
[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit(“DAHDI/4-1”, “”) in new stack
[2019-02-08 15:00:43] VERBOSE[2230] res_pjsip_logger.c: <— Received SIP response (517 bytes) from UDP:192.168.0.62:5160 —>
SIP/2.0 487 Request Cancelled
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport=5060;branch=z9hG4bKPj2f3c9dcb-8490-4dbe-9806-9d0d614bda6e;received=192.168.0.19
From: “Nelson, BC” sip:[email protected];tag=3ad7b6a5-8289-4142-b418-5409370b9213
To: sip:[email protected];tag=50142df6e6547d5
Call-ID: 7241848e-7247-4097-827f-5db2a3a745f3
CSeq: 14560 INVITE
User-Agent: Sangoma S500 V2.0.4.57
Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK
Content-Length: 0

[2019-02-08 15:00:43] VERBOSE[5379] res_pjsip_logger.c: <— Transmitting SIP request (418 bytes) to UDP:192.168.0.62:5160 —>
ACK sip:[email protected]:5160 SIP/2.0
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport;branch=z9hG4bKPj2f3c9dcb-8490-4dbe-9806-9d0d614bda6e
From: “Nelson, BC” sip:[email protected];tag=3ad7b6a5-8289-4142-b418-5409370b9213
To: sip:[email protected];tag=50142df6e6547d5
Call-ID: 7241848e-7247-4097-827f-5db2a3a745f3
CSeq: 14560 ACK
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Length: 0

[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] pbx.c: Executing [s@macro-auto-blkvm:7] ExecIf(“DAHDI/4-1”, “0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=4)”) in new stack
[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] pbx.c: Executing [s@macro-auto-blkvm:8] ExecIf(“DAHDI/4-1”, “0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=)”) in new stack
[2019-02-08 15:00:43] VERBOSE[2230] res_pjsip_logger.c: <— Received SIP response (502 bytes) from UDP:192.168.0.62:5160 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport=5060;branch=z9hG4bKPj2f3c9dcb-8490-4dbe-9806-9d0d614bda6e;received=192.168.0.19
From: “Nelson, BC” sip:[email protected];tag=3ad7b6a5-8289-4142-b418-5409370b9213
To: sip:[email protected];tag=50142df6e6547d5
Call-ID: 7241848e-7247-4097-827f-5db2a3a745f3
CSeq: 14560 CANCEL
User-Agent: Sangoma S500 V2.0.4.57
Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK
Content-Length: 0

[2019-02-08 15:00:43] VERBOSE[18209][C-00000039] bridge_channel.c: Channel DAHDI/4-1 joined ‘simple_bridge’ basic-bridge <9e2f9585-2c3d-4c41-a95a-ab1e32ba653d>
[2019-02-08 15:00:43] VERBOSE[18206][C-00000039] bridge_channel.c: Channel DAHDI/1-1 joined ‘simple_bridge’ basic-bridge <9e2f9585-2c3d-4c41-a95a-ab1e32ba653d>
[2019-02-08 15:00:43] VERBOSE[2230] res_pjsip_logger.c: <— Received SIP response (445 bytes) from UDP:10.8.0.17:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.8.0.1:5060;rport=5060;branch=z9hG4bKPj0b3973b2-e52c-4479-8038-1fe82a3a42a9
From: sip:[email protected];tag=97e602fe-85ca-46f9-908e-da3c2a02c4ef
To: “E-Home” sip:[email protected];tag=1ad2846ee1c0d01
Call-ID: [email protected]
CSeq: 29812 NOTIFY
User-Agent: Sangoma S500 V2.0.4.57
Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK
Content-Length: 0

[2019-02-08 15:00:43] VERBOSE[2230] res_pjsip_logger.c: <— Received SIP response (445 bytes) from UDP:10.8.0.17:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.8.0.1:5060;rport=5060;branch=z9hG4bKPj96a4181e-6cb7-4928-88e3-91e1845307c8
From: sip:[email protected];tag=42e62f0d-3a80-4d16-b54c-20534c8d1618
To: “E-Home” sip:[email protected];tag=83810dfb64c6303
Call-ID: [email protected]
CSeq: 17036 NOTIFY
User-Agent: Sangoma S500 V2.0.4.57
Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK
Content-Length: 0

[2019-02-08 15:00:43] VERBOSE[2230] res_pjsip_logger.c: <— Transmitting SIP response (937 bytes) to UDP:192.168.0.73:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.73:5060;rport=5060;received=192.168.0.73;branch=z9hG4bKda9e3d80
Call-ID: [email protected]
From: “Edwin” sip:[email protected];tag=a36d5635eb51bfa
To: sip:[email protected];tag=b01321bc-4b03-42a0-b704-42f4771a159e
CSeq: 21 INVITE
Server: FPBX-14.0.5.25(13.22.0)
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Contact: sip:my.wan.ip.addr:5060
Supported: 100rel, timer, replaces, norefersub
P-Asserted-Identity: “3195(Available)” sip:[email protected]
Content-Type: application/sdp
Content-Length: 296

v=0
o=- 6666 5 IN IP4 192.168.0.19
s=Asterisk
c=IN IP4 192.168.0.19
t=0 0
m=audio 11356 RTP/AVP 0 8 3 2 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[2019-02-08 15:00:47] VERBOSE[2230] res_pjsip_logger.c: <— Transmitting SIP response (937 bytes) to UDP:192.168.0.73:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.73:5060;rport=5060;received=192.168.0.73;branch=z9hG4bKda9e3d80
Call-ID: [email protected]
From: “Edwin” sip:[email protected];tag=a36d5635eb51bfa
To: sip:[email protected];tag=b01321bc-4b03-42a0-b704-42f4771a159e
CSeq: 21 INVITE
Server: FPBX-14.0.5.25(13.22.0)
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Contact: sip:my.wan.ip.addr:5060
Supported: 100rel, timer, replaces, norefersub
P-Asserted-Identity: “3195(Available)” sip:[email protected]
Content-Type: application/sdp
Content-Length: 296

v=0
o=- 6666 5 IN IP4 192.168.0.19
s=Asterisk
c=IN IP4 192.168.0.19
t=0 0
m=audio 11356 RTP/AVP 0 8 3 2 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[2019-02-08 15:00:51] VERBOSE[2230] res_pjsip_logger.c: <— Transmitting SIP response (937 bytes) to UDP:192.168.0.73:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.73:5060;rport=5060;received=192.168.0.73;branch=z9hG4bKda9e3d80
Call-ID: [email protected]
From: “Edwin” sip:[email protected];tag=a36d5635eb51bfa
To: sip:[email protected];tag=b01321bc-4b03-42a0-b704-42f4771a159e
CSeq: 21 INVITE
Server: FPBX-14.0.5.25(13.22.0)
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Contact: sip:my.wan.ip.addr:5060
Supported: 100rel, timer, replaces, norefersub
P-Asserted-Identity: “3195(Available)” sip:[email protected]
Content-Type: application/sdp
Content-Length: 296

v=0
o=- 6666 5 IN IP4 192.168.0.19
s=Asterisk
c=IN IP4 192.168.0.19
t=0 0
m=audio 11356 RTP/AVP 0 8 3 2 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[2019-02-08 15:00:55] VERBOSE[2230] res_pjsip_logger.c: <— Transmitting SIP response (937 bytes) to UDP:192.168.0.73:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.73:5060;rport=5060;received=192.168.0.73;branch=z9hG4bKda9e3d80
Call-ID: [email protected]
From: “Edwin” sip:[email protected];tag=a36d5635eb51bfa
To: sip:[email protected];tag=b01321bc-4b03-42a0-b704-42f4771a159e
CSeq: 21 INVITE
Server: FPBX-14.0.5.25(13.22.0)
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Contact: sip:my.wan.ip.addr:5060
Supported: 100rel, timer, replaces, norefersub
P-Asserted-Identity: “3195(Available)” sip:[email protected]
Content-Type: application/sdp
Content-Length: 296

v=0
o=- 6666 5 IN IP4 192.168.0.19
s=Asterisk
c=IN IP4 192.168.0.19
t=0 0
m=audio 11356 RTP/AVP 0 8 3 2 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

[2019-02-08 15:00:56] VERBOSE[2230] res_pjsip_logger.c: <— Transmitting SIP request (398 bytes) to UDP:192.168.0.73:5060 —>
BYE sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport;branch=z9hG4bKPjba53d711-7cb8-4169-b833-c7ef932302e1
From: sip:[email protected];tag=b01321bc-4b03-42a0-b704-42f4771a159e
To: “Edwin” sip:[email protected];tag=a36d5635eb51bfa
Call-ID: [email protected]
CSeq: 2233 BYE
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Length: 0

[2019-02-08 15:00:56] VERBOSE[2230] res_pjsip_logger.c: <— Received SIP response (479 bytes) from UDP:192.168.0.73:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport=5060;branch=z9hG4bKPjba53d711-7cb8-4169-b833-c7ef932302e1;received=192.168.0.19
From: sip:[email protected];tag=b01321bc-4b03-42a0-b704-42f4771a159e
To: “Edwin” sip:[email protected];tag=a36d5635eb51bfa
Call-ID: [email protected]
CSeq: 2233 BYE
User-Agent: Sangoma S500 V2.0.4.57
Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK
Content-Length: 0

[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] bridge_channel.c: Channel PJSIP/3160-0000002e left ‘simple_bridge’ basic-bridge
[2019-02-08 15:00:56] VERBOSE[18205][C-00000038] bridge_channel.c: Channel PJSIP/3195-0000002f left ‘simple_bridge’ basic-bridge
[2019-02-08 15:00:56] VERBOSE[7166] res_pjsip_logger.c: <— Transmitting SIP request (452 bytes) to UDP:192.168.0.58:59273 —>
BYE sip:[email protected]:59273 SIP/2.0
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport;branch=z9hG4bKPj21ef00f1-6a01-44e1-a8f7-be0fda3a1ee3
From: “Edwin” sip:[email protected];tag=d80abe5e-66cc-4425-907a-b79acec72df8
To: sip:[email protected];rinstance=f13350a4f8e8b87a;tag=861c774f
Call-ID: fdb15862-49ef-4103-94d9-66d0705b6ef9
CSeq: 14775 BYE
Reason: Q.850;cause=16
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Length: 0

[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] app_macro.c: Spawn extension (macro-dial-one, s, 54) exited non-zero on ‘PJSIP/3160-0000002e’ in macro ‘dial-one’
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] app_macro.c: Spawn extension (macro-exten-vm, s, 26) exited non-zero on ‘PJSIP/3160-0000002e’ in macro ‘exten-vm’
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] pbx.c: Spawn extension (ext-local, 3195, 2) exited non-zero on ‘PJSIP/3160-0000002e’
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] pbx.c: Executing [h@ext-local:1] Macro(“PJSIP/3160-0000002e”, “hangupcall,”) in new stack
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] pbx.c: Executing [s@macro-hangupcall:1] GotoIf(“PJSIP/3160-0000002e”, “1?theend”) in new stack
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] pbx.c: Executing [s@macro-hangupcall:3] ExecIf(“PJSIP/3160-0000002e”, “0?Set(CDR(recordingfile)=)”) in new stack
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] pbx.c: Executing [s@macro-hangupcall:4] NoOp(“PJSIP/3160-0000002e”, "PJSIP/3195-0000002f montior file= ") in new stack
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] pbx.c: Executing [s@macro-hangupcall:5] GotoIf(“PJSIP/3160-0000002e”, “1?skipagi”) in new stack
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] pbx_builtins.c: Goto (macro-hangupcall,s,7)
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] pbx.c: Executing [s@macro-hangupcall:7] Hangup(“PJSIP/3160-0000002e”, “”) in new stack
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] app_macro.c: Spawn extension (macro-hangupcall, s, 7) exited non-zero on ‘PJSIP/3160-0000002e’ in macro ‘hangupcall’
[2019-02-08 15:00:56] VERBOSE[18166][C-00000038] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on ‘PJSIP/3160-0000002e’
[2019-02-08 15:00:56] VERBOSE[9190] res_pjsip_logger.c: <— Transmitting SIP request (828 bytes) to UDP:192.168.0.62:5060 —>
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport;branch=z9hG4bKPj18fbc0fc-7fee-4941-ba1f-c2cc98658e19
From: sip:[email protected];tag=2966c454-2d42-49f2-91c6-dad2d78c6046
To: “Cindy” sip:[email protected];tag=b25dfc03ae1d540
Contact: sip:my.wan.ip.addr:5060
Call-ID: [email protected]
CSeq: 27231 NOTIFY
Event: dialog
Subscription-State: active;expires=41
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Type: application/dialog-info+xml
Content-Length: 231

<?xml version="1.0" encoding="UTF-8"?> terminated

[2019-02-08 15:00:56] VERBOSE[7166] res_pjsip_logger.c: <— Transmitting SIP request (805 bytes) to UDP:10.8.0.17:5060 —>
NOTIFY sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 10.8.0.1:5060;rport;branch=z9hG4bKPjf03e5614-94e0-49b6-9262-0af2b5bf7d2d
From: sip:[email protected];tag=8dbe3380-0583-4b6e-92c6-9306592d5f5e
To: “E-Home” sip:[email protected];tag=b7080b58ad68174
Contact: sip:10.8.0.1:5060
Call-ID: [email protected]
CSeq: 17118 NOTIFY
Event: dialog
Subscription-State: active;expires=250
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Type: application/dialog-info+xml
Content-Length: 232

<?xml version="1.0" encoding="UTF-8"?> terminated

[2019-02-08 15:00:56] VERBOSE[2230] res_pjsip_logger.c: <— Received SIP response (483 bytes) from UDP:192.168.0.62:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport=5060;branch=z9hG4bKPj18fbc0fc-7fee-4941-ba1f-c2cc98658e19;received=192.168.0.19
From: sip:[email protected];tag=2966c454-2d42-49f2-91c6-dad2d78c6046
To: “Cindy” sip:[email protected];tag=b25dfc03ae1d540
Call-ID: [email protected]
CSeq: 27231 NOTIFY
User-Agent: Sangoma S500 V2.0.4.57
Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK
Content-Length: 0

[2019-02-08 15:00:56] VERBOSE[2230] res_pjsip_logger.c: <— Received SIP response (445 bytes) from UDP:10.8.0.17:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.8.0.1:5060;rport=5060;branch=z9hG4bKPjf03e5614-94e0-49b6-9262-0af2b5bf7d2d
From: sip:[email protected];tag=8dbe3380-0583-4b6e-92c6-9306592d5f5e
To: “E-Home” sip:[email protected];tag=b7080b58ad68174
Call-ID: [email protected]
CSeq: 17118 NOTIFY
User-Agent: Sangoma S500 V2.0.4.57
Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK
Content-Length: 0

[2019-02-08 15:00:56] VERBOSE[2230] res_pjsip_logger.c: <— Received SIP response (460 bytes) from UDP:192.168.0.58:59273 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport=5060;branch=z9hG4bKPj21ef00f1-6a01-44e1-a8f7-be0fda3a1ee3;received=192.168.0.19
Contact: sip:[email protected]:59273
To: sip:[email protected];rinstance=f13350a4f8e8b87a;tag=861c774f
From: “Edwin” sip:[email protected];tag=d80abe5e-66cc-4425-907a-b79acec72df8
Call-ID: fdb15862-49ef-4103-94d9-66d0705b6ef9
CSeq: 14775 BYE
User-Agent: X-Lite release 5.4.0 stamp 94388
Content-Length: 0

[2019-02-08 15:00:58] VERBOSE[5379] res_pjsip_logger.c: <— Transmitting SIP request (428 bytes) to UDP:192.168.0.74:5160 —>
OPTIONS sip:[email protected]:5160 SIP/2.0
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport;branch=z9hG4bKPja20ce31c-2798-4199-94b4-217cd28da511
From: sip:[email protected];tag=485ab16a-26ca-4cf0-8ac9-7044febb8610
To: sip:[email protected]
Contact: sip:[email protected]:5060
Call-ID: 56a99958-47d0-4c71-a0ef-4c27e3c03860
CSeq: 35176 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Length: 0

[2019-02-08 15:00:58] VERBOSE[2230] res_pjsip_logger.c: <— Received SIP response (484 bytes) from UDP:192.168.0.74:5160 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP my.wan.ip.addr:5060;rport=5060;branch=z9hG4bKPja20ce31c-2798-4199-94b4-217cd28da511;received=192.168.0.19
From: sip:[email protected];tag=485ab16a-26ca-4cf0-8ac9-7044febb8610
To: sip:[email protected];tag=4f0e98b2e1d4cae
Call-ID: 56a99958-47d0-4c71-a0ef-4c27e3c03860
CSeq: 35176 OPTIONS
User-Agent: Sangoma S500 V2.0.4.57
Allow: INVITE, ACK, UPDATE, INFO, CANCEL, BYE, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, PRACK
Content-Length: 0

12

Not the full call but format was better.

So both of these phones are on the same network as the PBX?

13

Yes they are on the same LAN, I tried to post all of it but it was too big and not allowed, hence trying pastebin.

14

You have your local networks defined in your PJSIP transports? This shouldn’t be using the external address for devices on the same network unless it doesn’t think the network is local. Double check that.

15

Yes, that’s what puzzled me. I thought NAT was set to no, looking…

16

This looks better Tom;

<— Transmitting SIP request (426 bytes) to UDP:192.168.0.58:59273 —>
ACK sip:[email protected]:59273 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.19:5060;rport;branch=z9hG4bKPj6502c181-e3c3-4c5e-9ab3-82ce4efb7d6e
From: “Edwin” sip:[email protected];tag=1df7c7a9-6fc5-4c30-82d2-a47f5fb492a5
To: sip:[email protected];rinstance=f13350a4f8e8b87a;tag=a2dac47e
Call-ID: b6ba05c5-6e40-4193-a4e9-26462867dafa
CSeq: 28317 ACK
Max-Forwards: 70
User-Agent: FPBX-14.0.5.25(13.22.0)
Content-Length: 0

<— Transmitting SIP response (936 bytes) to UDP:192.168.0.73:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.0.73:5060;rport=5060;received=192.168.0.73;branch=z9hG4bKb475453e
Call-ID: [email protected]
From: “Edwin” sip:[email protected];tag=54dd606bc2edb90
To: sip:[email protected];tag=1d874db1-dcb1-478d-86a0-323c594eef10
CSeq: 21 INVITE
Server: FPBX-14.0.5.25(13.22.0)
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, MESSAGE, REFER
Contact: sip:192.168.0.19:5060
Supported: 100rel, timer, replaces, norefersub
P-Asserted-Identity: “3195(Available)” sip:[email protected]
Content-Type: application/sdp
Content-Length: 297

v=0
o=- 6666 11 IN IP4 192.168.0.19
s=Asterisk
c=IN IP4 192.168.0.19
t=0 0
m=audio 14130 RTP/AVP 0 8 3 2 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

<— Received SIP request (406 bytes) from UDP:192.168.0.73:5060 —>
ACK sip:192.168.0.19:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.0.73:5060;branch=z9hG4bK2397495877
From: “Edwin” sip:[email protected];tag=54dd606bc2edb90
To: sip:[email protected];tag=1d874db1-dcb1-478d-86a0-323c594eef10
Call-ID: [email protected]
CSeq: 21 ACK
Contact: sip:[email protected]:5060;transport=UDP
Max-Forwards: 70
User-Agent: Sangoma S500 V2.0.4.57
Content-Length: 0

In general SIP Settings> NAT Settings> External Address was populated with my WAN address. I’ve no idea why. it all started two days ago.

Calls are no longer dropping!

Thank you very much for your time Tom and giving me a pointer. Much appreciated!

17

Because your PBX is behind NAT. The PBX needs to know when to use the external IP, like with calls to your provider. You should have the LOCAL NETWORKS defined with 192.168.0.0/24 to tell the PBX that when requests to/from that subnet are made to use the internal IP (local) vs when calling the provider (external)

1 Like
18

That makes sense, my provider is via DAHDI so I would never need to go external.
Again, I appreciate your help.

19

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