FreePBX 15 - These two specific local extensions can call any other extension except each other. The call connects but there is no audio. After the attempt, one of the extensions is ‘busy’ and sends the callers to VM. This started happening after a recent automatic module upgrade. How can I find the problem?
1 Like
I did a *80100 from ext 123. Call connected but no audio. Can you tell why? Here’s the log for the call:
[2021-07-16 09:55:21] VERBOSE[10378] netsock2.c: Using SIP RTP Audio TOS bits 184
[2021-07-16 09:55:21] VERBOSE[10378] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.
[2021-07-16 09:55:21] VERBOSE[10378] netsock2.c: Using SIP RTP Audio CoS mark 5
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@from-internal:1] Goto("PJSIP/123-00000055", "ext-intercom,*80100,1") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx_builtins.c: Goto (ext-intercom,*80100,1)
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:1] Macro("PJSIP/123-00000055", "user-callerid,") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/123-00000055", "TOUCH_MONITOR=1626454521.900") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/123-00000055", "AMPUSER=123") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:3] Set("PJSIP/123-00000055", "HOTDESCKCHAN=123-00000055") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:4] Set("PJSIP/123-00000055", "HOTDESKEXTEN=123") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/123-00000055", "HOTDESKCALL=0") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:6] ExecIf("PJSIP/123-00000055", "0?Set(HOTDESKCALL=1)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:7] ExecIf("PJSIP/123-00000055", "0?Set(CALLERID(name)=)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("PJSIP/123-00000055", "0?report") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:9] ExecIf("PJSIP/123-00000055", "1?Set(REALCALLERIDNUM=123)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/123-00000055", "AMPUSER=123") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:11] GotoIf("PJSIP/123-00000055", "0?limit") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:12] Set("PJSIP/123-00000055", "AMPUSERCIDNAME=Toni Essman") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("PJSIP/123-00000055", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:14] GotoIf("PJSIP/123-00000055", "0?report") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:15] Set("PJSIP/123-00000055", "AMPUSERCID=123") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:16] Set("PJSIP/123-00000055", "__DIAL_OPTIONS=Ttr") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:17] Set("PJSIP/123-00000055", "CALLERID(all)="Toni Essman" <123>") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:18] ExecIf("PJSIP/123-00000055", "0?Set(CUSDIAL=)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:19] ExecIf("PJSIP/123-00000055", "0?Set(CALLERID(all)="Toni Essman" <123>)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:20] GotoIf("PJSIP/123-00000055", "0?limit") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:21] ExecIf("PJSIP/123-00000055", "0?Set(GROUP(concurrency_limit)=123)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:22] ExecIf("PJSIP/123-00000055", "0?Set(CHANNEL(language)=)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:23] NoOp("PJSIP/123-00000055", "Macro Depth is 1") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:24] GotoIf("PJSIP/123-00000055", "1?report2:macroerror") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx_builtins.c: Goto (macro-user-callerid,s,25)
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:25] GotoIf("PJSIP/123-00000055", "0?continue") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:26] ExecIf("PJSIP/123-00000055", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:27] Set("PJSIP/123-00000055", "__TTL=64") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:28] GotoIf("PJSIP/123-00000055", "1?continue") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx_builtins.c: Goto (macro-user-callerid,s,44)
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:44] Set("PJSIP/123-00000055", "CALLERID(number)=123") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:45] Set("PJSIP/123-00000055", "CALLERID(name)=Toni Essman") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:46] GotoIf("PJSIP/123-00000055", "0?cnum") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:47] Set("PJSIP/123-00000055", "CDR(cnam)=Toni Essman") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:48] Set("PJSIP/123-00000055", "CDR(cnum)=123") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-user-callerid:49] Set("PJSIP/123-00000055", "CHANNEL(language)=en") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:2] Set("PJSIP/123-00000055", "dialnumber=100") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:3] Set("PJSIP/123-00000055", "INTERCOM_CALL=TRUE") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:4] Gosub("PJSIP/123-00000055", "sub-record-check,s,1(exten,100)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/123-00000055", "0?initialized") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/123-00000055", "__REC_STATUS=INITIALIZED") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/123-00000055", "NOW=1626454521") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/123-00000055", "__DAY=16") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/123-00000055", "__MONTH=07") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/123-00000055", "__YEAR=2021") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/123-00000055", "__TIMESTR=20210716-095521") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/123-00000055", "__FROMEXTEN=123") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/123-00000055", "__MON_FMT=wav") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/123-00000055", "Recordings initialized") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/123-00000055", "1?Set(ARG3=dontcare)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/123-00000055", "REC_POLICY_MODE_SAVE=") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/123-00000055", "0?Set(REC_STATUS=NO)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/123-00000055", "5?checkaction") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx_builtins.c: Goto (sub-record-check,s,17)
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/123-00000055", "1?sub-record-check,exten,1") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:1] NoOp("PJSIP/123-00000055", "Exten Recording Check between 123 and 100") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:2] Set("PJSIP/123-00000055", "CALLTYPE=internal") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:3] ExecIf("PJSIP/123-00000055", "0?Set(CALLTYPE=)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:4] Set("PJSIP/123-00000055", "CALLEE=dontcare") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:5] ExecIf("PJSIP/123-00000055", "0?Set(CALLEE=dontcare)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:6] GotoIf("PJSIP/123-00000055", "0?callee") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:7] GotoIf("PJSIP/123-00000055", "1?caller") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx_builtins.c: Goto (sub-record-check,exten,13)
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:13] Set("PJSIP/123-00000055", "RECMODE=dontcare") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:14] Set("PJSIP/123-00000055", "CALLERRECMODE=dontcare") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:15] Set("PJSIP/123-00000055", "CALEERECMODE=dontcare") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:16] GotoIf("PJSIP/123-00000055", "0?processnormal") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:17] ExecIf("PJSIP/123-00000055", "0?Set(RECMODE=dontcare)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:18] ExecIf("PJSIP/123-00000055", "0?Set(RECMODE=dontcare)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:19] ExecIf("PJSIP/123-00000055", "0?Set(RECMODE=dontcare)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:20] ExecIf("PJSIP/123-00000055", "0?Set(RECMODE=dontcare)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:21] ExecIf("PJSIP/123-00000055", "0?Set(RECMODE=dontcare)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:22] ExecIf("PJSIP/123-00000055", "1?Set(RECMODE=dontcare)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:23] Gosub("PJSIP/123-00000055", "recordcheck,1(dontcare,internal,100)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/123-00000055", "Starting recording check against dontcare") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/123-00000055", "dontcare") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/123-00000055", "") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [exten@sub-record-check:24] Return("PJSIP/123-00000055", "") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:5] GotoIf("PJSIP/123-00000055", "0?end") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:6] GotoIf("PJSIP/123-00000055", "0?end") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:7] GotoIf("PJSIP/123-00000055", "0?allow") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:8] GotoIf("PJSIP/123-00000055", "0?nointercom") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:9] GotoIf("PJSIP/123-00000055", "0?nointercom") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:10] Set("PJSIP/123-00000055", "DEVICES=100") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:11] GotoIf("PJSIP/123-00000055", "0?end") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:12] Set("PJSIP/123-00000055", "OVERRIDE=reject") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:13] Set("PJSIP/123-00000055", "LOOPCNT=1") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:14] Set("PJSIP/123-00000055", "_SIPURI=") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:15] Set("PJSIP/123-00000055", "_ALERTINFO=Ring Answer") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:16] Set("PJSIP/123-00000055", "_CALLINFO=<uri>;answer-after=0") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:17] Set("PJSIP/123-00000055", "_SIPURI=intercom=true") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:18] Set("PJSIP/123-00000055", "_DTIME=5") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:19] Set("PJSIP/123-00000055", "_ANSWERMACRO=") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:20] GotoIf("PJSIP/123-00000055", "0?pagemode") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:21] Macro("PJSIP/123-00000055", "autoanswer,100") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:1] GotoIf("PJSIP/123-00000055", "0?knowndial") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:2] Set("PJSIP/123-00000055", "DEVICE=PJSIP/100") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:3] GotoIf("PJSIP/123-00000055", "1?dopjsip") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx_builtins.c: Goto (macro-autoanswer,s,6)
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:6] Set("PJSIP/123-00000055", "KNOWNDIAL=PJSIP/100/sip:[email protected]:5060") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:7] GotoIf("PJSIP/123-00000055", "1?knowndial") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx_builtins.c: Goto (macro-autoanswer,s,19)
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:19] Set("PJSIP/123-00000055", "DIAL=PJSIP/100/sip:[email protected]:5060") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:20] GotoIf("PJSIP/123-00000055", "0?macro") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:21] GotoIf("PJSIP/123-00000055", "1?pjsipua") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx_builtins.c: Goto (macro-autoanswer,s,24)
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:24] Set("PJSIP/123-00000055", "AOR=100") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:25] Set("PJSIP/123-00000055", "CONTACT=100;@5476b4bf54b0db9b68a23cfda02117b7") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:26] Set("PJSIP/123-00000055", "USERAGENT=Aastra 57i/3.3.1.4322") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:27] ExecIf("PJSIP/123-00000055", "0?Set(USERAGENT=)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:28] ExecIf("PJSIP/123-00000055", "0?Set(PAGE_VOL=;volume=)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:29] ExecIf("PJSIP/123-00000055", "0?Set(ALERTINFO=ring-answer)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:30] ExecIf("PJSIP/123-00000055", "0?Set(CALLINFO=<sip:broadworks.net>;answer-after=0)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:31] ExecIf("PJSIP/123-00000055", "0?Set(ALERTINFO=<http://example.com>;info=alert-autoanswer)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:32] ExecIf("PJSIP/123-00000055", "0?Set(ALERTINFO=Intercom)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:33] ExecIf("PJSIP/123-00000055", "0?Set(ALERTINFO=Alert-Info: Auto Answer)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:34] ExecIf("PJSIP/123-00000055", "0?Set(ALERTINFO=<http://www.sangoma.com>\;info=external)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:35] ExecIf("PJSIP/123-00000055", "0?Set(ALERTINFO=ring-answer)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:36] ExecIf("PJSIP/123-00000055", "0?Set(ALERTINFO=<http://www.sangoma.com>;info=external)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@macro-autoanswer:37] ExecIf("PJSIP/123-00000055", "1?Set(__SIP_URI_OPTIONS=intercom=true)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:22] Set("PJSIP/123-00000055", "_DOPTIONS=A(beep)b(autoanswer^s^1(Ring Answer,<uri>;answer-after=0))") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:23] ChanIsAvail("PJSIP/123-00000055", "PJSIP/100,s") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:24] ExecIf("PJSIP/123-00000055", "0?Set(AVAILORIGCHAN=PJSIP/100)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:25] GotoIf("PJSIP/123-00000055", "1?continue") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx_builtins.c: Goto (ext-intercom,*80100,30)
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:30] NoOp("PJSIP/123-00000055", "Continuing with page") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:31] GotoIf("PJSIP/123-00000055", "0?godial") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:32] Set("PJSIP/123-00000055", "CONNECTEDLINE(name,i)=Kim Leon") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:33] Set("PJSIP/123-00000055", "CONNECTEDLINE(num)=100") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [*80100@ext-intercom:34] Dial("PJSIP/123-00000055", "PJSIP/100/sip:[email protected]:5060,5,IA(beep)b(autoanswer^s^1(Ring Answer,<uri>;answer-after=0))") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] app_stack.c: PJSIP/100-00000057 Internal Gosub(autoanswer,s,1(Ring Answer,<uri>;answer-after=0)) start
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@autoanswer:1] GosubIf("PJSIP/100-00000057", "1?func-set-sipheader,s,1(Alert-Info,Ring Answer)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-set-sipheader:1] NoOp("PJSIP/100-00000057", "Sip Add Header function called. Adding Alert-Info = Ring Answer") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-set-sipheader:2] Set("PJSIP/100-00000057", "HASH(__SIPHEADERS,Alert-Info)=Ring Answer") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-set-sipheader:3] Return("PJSIP/100-00000057", "") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@autoanswer:2] GosubIf("PJSIP/100-00000057", "1?func-set-sipheader,s,1(Call-Info,<uri>;answer-after=0)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-set-sipheader:1] NoOp("PJSIP/100-00000057", "Sip Add Header function called. Adding Call-Info = <uri>;answer-after=0") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-set-sipheader:2] Set("PJSIP/100-00000057", "HASH(__SIPHEADERS,Call-Info)=<uri>;answer-after=0") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-set-sipheader:3] Return("PJSIP/100-00000057", "") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@autoanswer:3] Gosub("PJSIP/100-00000057", "func-apply-sipheaders,s,1()") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("PJSIP/100-00000057", "0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("PJSIP/100-00000057", "Applying SIP Headers to channel PJSIP/100-00000057") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/100-00000057", "TECH=PJSIP") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:4] Set("PJSIP/100-00000057", "SIPHEADERKEYS=Call-Info,Alert-Info") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/100-00000057", "1") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:6] Set("PJSIP/100-00000057", "sipheader=<uri>;answer-after=0") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:7] ExecIf("PJSIP/100-00000057", "0?SIPRemoveHeader(Call-Info:)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:8] ExecIf("PJSIP/100-00000057", "0?Set(PJSIP_HEADER(remove,Call-Info)=)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("PJSIP/100-00000057", "0?Set(sipheader=<http://127.0.0.1>;info=<uri>;answer-after=0)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("PJSIP/100-00000057", "0?Set(sipheader=<http://127.0.0.1><uri>;answer-after=0)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("PJSIP/100-00000057", "0?SIPAddHeader(Call-Info:<uri>;answer-after=0)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:12] ExecIf("PJSIP/100-00000057", "1?Set(PJSIP_HEADER(add,Call-Info)=<uri>;answer-after=0)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:13] EndWhile("PJSIP/100-00000057", "") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/100-00000057", "1") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:6] Set("PJSIP/100-00000057", "sipheader=Ring Answer") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:7] ExecIf("PJSIP/100-00000057", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:8] ExecIf("PJSIP/100-00000057", "0?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("PJSIP/100-00000057", "1?Set(sipheader=<http://127.0.0.1>;info=Ring Answer)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("PJSIP/100-00000057", "0?Set(sipheader=<http://127.0.0.1><http://127.0.0.1>;info=Ring Answer)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("PJSIP/100-00000057", "0?SIPAddHeader(Alert-Info:<http://127.0.0.1>;info=Ring Answer)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:12] ExecIf("PJSIP/100-00000057", "1?Set(PJSIP_HEADER(add,Alert-Info)=<http://127.0.0.1>;info=Ring Answer)") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:13] EndWhile("PJSIP/100-00000057", "") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/100-00000057", "0") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@func-apply-sipheaders:14] Return("PJSIP/100-00000057", "") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] pbx.c: Executing [s@autoanswer:4] Return("PJSIP/100-00000057", "") in new stack
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] app_stack.c: Spawn extension (from-internal, *80100, 1) exited non-zero on 'PJSIP/100-00000057'
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] app_stack.c: PJSIP/100-00000057 Internal Gosub(autoanswer,s,1(Ring Answer,<uri>;answer-after=0)) complete GOSUB_RETVAL=
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] app_dial.c: Called PJSIP/100/sip:[email protected]:5060
[2021-07-16 09:55:21] VERBOSE[10378] netsock2.c: Using SIP RTP Audio TOS bits 184
[2021-07-16 09:55:21] VERBOSE[10378] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.
[2021-07-16 09:55:21] VERBOSE[10378] netsock2.c: Using SIP RTP Audio CoS mark 5
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] app_dial.c: Connected line update to PJSIP/123-00000055 prevented.
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] app_dial.c: PJSIP/100-00000057 answered PJSIP/123-00000055
[2021-07-16 09:55:21] VERBOSE[2853][C-00000044] file.c: <PJSIP/100-00000057> Playing 'beep.ulaw' (language 'en')
[2021-07-16 09:55:22] VERBOSE[2868][C-00000044] bridge_channel.c: Channel PJSIP/100-00000057 joined 'simple_bridge' basic-bridge <5e1e3a8c-eddb-4165-8a8f-b41d6cbfd4c9>
[2021-07-16 09:55:22] VERBOSE[2853][C-00000044] bridge_channel.c: Channel PJSIP/123-00000055 joined 'simple_bridge' basic-bridge <5e1e3a8c-eddb-4165-8a8f-b41d6cbfd4c9>
[2021-07-16 09:55:24] VERBOSE[2318] res_pjsip_endpoint_identifier_dpma.c: Updating DPMA user '151' uri='pjsip:76.170.159.205:5060;transport=' ua='Sangoma S406 V3.0.4.79'
[2021-07-16 09:55:24] NOTICE[10366] res_pjsip_exten_state.c: Endpoint '151' state subscription failed: Extension '*992*15*151*1' does not exist in context 'from-internal' or has no associated hint
[2021-07-16 09:55:24] NOTICE[10378] res_pjsip_exten_state.c: Endpoint '151' state subscription failed: Extension '*992*3*151*1' does not exist in context 'from-internal' or has no associated hint
[2021-07-16 09:55:25] NOTICE[7899] res_pjsip_exten_state.c: Endpoint '151' state subscription failed: Extension '*992*11*151*1' does not exist in context 'from-internal' or has no associated hint
[2021-07-16 09:55:28] VERBOSE[2853][C-00000044] bridge_channel.c: Channel PJSIP/123-00000055 left 'native_rtp' basic-bridge <5e1e3a8c-eddb-4165-8a8f-b41d6cbfd4c9>
[2021-07-16 09:55:28] VERBOSE[2853][C-00000044] pbx.c: Spawn extension (ext-intercom, *80100, 34) exited non-zero on 'PJSIP/123-00000055'
[2021-07-16 09:55:28] VERBOSE[2868][C-00000044] bridge_channel.c: Channel PJSIP/100-00000057 left 'native_rtp' basic-bridge <5e1e3a8c-eddb-4165-8a8f-b41d6cbfd4c9>
[2021-07-16 09:55:57] NOTICE[7899] res_pjsip_exten_state.c: Endpoint '102' state subscription failed: Extension '193' does not exist in context 'from-internal' or has no associated hint
[2021-07-16 09:56:26] NOTICE[10366] res_pjsip/pjsip_distributor.c: Request 'INVITE' from '<sip:[email protected]>' failed for '40.121.221.57:61631' (callid: 1926241433-1407422033-773462983) - Failed to authenticate
[2021-07-16 09:56:26] NOTICE[10378] res_pjsip/pjsip_distributor.c: Request 'INVITE' from '<sip:[email protected]>' failed for '40.121.221.57:61631' (callid: 1926241433-1407422033-773462983) - Failed to authenticate
[2021-07-16 09:56:26] NOTICE[10378] res_pjsip/pjsip_distributor.c: Request 'INVITE' from '<sip:[email protected]>' failed for '40.121.221.57:61631' (callid: 1926241433-1407422033-773462983) - Failed to authenticate
[2021-07-16 09:56:27] NOTICE[7899] res_pjsip/pjsip_distributor.c: Request 'INVITE' from '<sip:[email protected]>' failed for '40.121.221.57:61631' (callid: 1926241433-1407422033-773462983) - No matching endpoint found after 5 tries in 0.418 ms
[2021-07-16 09:56:27] NOTICE[7899] res_pjsip/pjsip_distributor.c: Request 'INVITE' from '<sip:[email protected]>' failed for '40.121.221.57:61631' (callid: 1926241433-1407422033-773462983) - Failed to authenticate
[2021-07-16 09:56:27] NOTICE[10366] res_pjsip/pjsip_distributor.c: Request 'INVITE' from '<sip:[email protected]>' failed for '40.121.221.57:61631' (callid: 1926241433-1407422033-773462983) - No matching endpoint found after 6 tries in 0.523 ms
[2021-07-16 09:56:27] NOTICE[10366] res_pjsip/pjsip_distributor.c: Request 'INVITE' from '<sip:[email protected]>' failed for '40.121.221.57:61631' (callid: 1926241433-1407422033-773462983) - Failed to authenticate
[2021-07-16 09:56:44] VERBOSE[2800] asterisk.c: Remote UNIX connection
[2021-07-16 09:56:44] VERBOSE[3156] asterisk.c: Remote UNIX connection disconnected
[2021-07-16 09:56:44] VERBOSE[2800] asterisk.c: Remote UNIX connection
[2021-07-16 09:56:44] VERBOSE[3158] asterisk.c: Remote UNIX connection disconnected
[2021-07-16 09:56:44] VERBOSE[2800] asterisk.c: Remote UNIX connection
[2021-07-16 09:56:44] VERBOSE[3160] asterisk.c: Remote UNIX connection disconnected
[2021-07-16 09:56:55] NOTICE[10366] res_pjsip_exten_state.c: Endpoint '102' state subscription failed: Extension '193' does not exist in context 'from-internal' or has no associated hint
To see the audio details, please include a SIP trace. At the Asterisk command prompt, type
pjsip set logger on
make another test call, paste the Asterisk log for the call at pastebin.freepbx.org and post the link here. (Don’t paste directly into your post.)
However, if I’m interpreting the log correctly, it appears that the extensions are registering to the public IP address of the PBX, even though they are local. This can work, but is depending on the router/firewall to ‘hairpin’ properly. Is there some reason why you don’t register to the PBX local (LAN) address?
1 Like
https-//pastebin.freepbx.org/view/1e7f6b9a
Here’s the link to the log with the SIP trace.
I’m using a class c address for all devices in my network. My firewall won’t let most devices be accessed from the outside.
Classfull subnetting has not been a thing for decades.
Repeat this for a working set of extensions.
While it’s no longer a thing, it does help us to know that he is using a full /24 for his network. The thing I want to know is which /24? 192.168.0.0/24 is technically a class C address, so is he using routable or non-routable? Is his traffic trying to reflect through two NATs and stuff like that?
Looking through the log, there are a couple of things that make me ponder. The first is “are these extensions both on the same server?” I see traffic from extension 183 on one local server to 183 on a different local server. While I have no idea why that wouldn’t work, I’m not sure it would.
It also appears that everything is on the public network side, yet he talks about using a firewall. I’m a little confused by the apparent network setup, so if @BenWeinberg could speak to that a little (where are the firewalls and routers in this network, and are there more than one Asterisk server, for a start) it might help explain where we’re going.
My class c adddress is provided by my isp and goes through a router and firewall that does not nat.
Ext 183 if off-site and is no doubt behind a nat. The phone uses my network ip address for the server.
Most users don’t have the luxury of 255 ip addresses that can be reached directly from the internet without having to deal with nat.
I personally don’t see that as a luxury, more a waste if IP4 address space. Many of us are more than happy that we only have one external IP to worry about.
1 Like
Within your local network, which is an entirely routable /24 subnet, there should be no problems communicating with any two particular extensions. The *80100 is an intercom call, so it’s a little different than a normal SIP call. When you just dial 100 from the other phone, does the call go through and do you get sound?
When I dial 100, the phone rings, and when answered, has no audio.
Even with a one to one NAT your router might still need to forward from the outside (and in your case also hairpin for the inside) udp ports 10000-20000 to your PBX)
Starting at line 555 in https://pastebin.freepbx.org/view/1e7f6b9a , Asterisk is sending a strange re-invite with its IP address but port 3000 (what the phones use but outside of Asterisk’s RTP range of 10000-20000). I don’t know whether this is just a bug in pjsip or Asterisk, or whether it’s related to use of public IPv4 space for a local network.
I also don’t know what triggered the need for a re-invite. It may be easier to eliminate that than to track down the bug. If you have Direct Media set for either extension, turn that off. Also, try limiting the enabled codecs for both extensions (both in the device config and on the Advanced tab for the extensions) to ulaw only. With luck, that will eliminate the re-invite. If those don’t help, please paste another log.
For both ext 100 and 123, the Direct Media was set to Yes. I set them both to no and that fixed it and I get audio between ext 100 and 123 now!
I checked the log listing and couldn’t find an Invite statment with the ip and port 3000. I searched for 3000 and found several of these: m=audio 3000 RTP/AVP 0
Is that the invite?
I then tested two other extensions that had Direct Media set to yes and found that they work anyway. These are all the same Aastra phones of various models; 53i or 57i. Curious?
I won’t argue with success. My bacon is saved. Thank you to all on this list who helped.
This topic was automatically closed 31 days after the last reply. New replies are no longer allowed.