Innovaphone 111 can call, but can't be called

pge · May 5, 2022, 10:44am

Hey guys!
Im having trouble getting innovaphones (111 + 222) working on my freepbx.
I have an 111 that seems registered and can perform internal and external calls, but refuses to be called at all.

Innovaphone Webinterface:

Call log from 995 (grandstream) to 401 (innovaphone 111)

61930[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [401@from-internal:1] GotoIf("PJSIP/995-000204e2", "1?ext-local,401,1:followme-check,401,1") in new stack
61931[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (ext-local,401,1)
61932[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [401@ext-local:1] Set("PJSIP/995-000204e2", "__RINGTIMER=15") in new stack
61933[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [401@ext-local:2] ExecIf("PJSIP/995-000204e2", "0?Set(__CWIGNORE=)") in new stack
61934[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [401@ext-local:3] Macro("PJSIP/995-000204e2", "exten-vm,novm,401,0,0,0") in new stack
61935[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:1] Macro("PJSIP/995-000204e2", "user-callerid,") in new stack
61936[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/995-000204e2", "TOUCH_MONITOR=1651747141.201768") in new stack
61937[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/995-000204e2", "CHANCONTEXT=") in new stack
61938[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:3] Set("PJSIP/995-000204e2", "CHANCONTEXT=") in new stack
61939[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:4] Set("PJSIP/995-000204e2", "CHANEXTENCONTEXT=995-000204e2") in new stack
61940[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/995-000204e2", "CHANEXTEN=995-000204e2") in new stack
61941[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:6] Set("PJSIP/995-000204e2", "CALLERID(number)=995") in new stack
61942[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/995-000204e2", "AMPUSER=995") in new stack
61943[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:8] Set("PJSIP/995-000204e2", "HOTDESCKCHAN=995-000204e2") in new stack
61944[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:9] Set("PJSIP/995-000204e2", "HOTDESKEXTEN=995") in new stack
61945[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/995-000204e2", "HOTDESKCALL=0") in new stack
61946[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:11] ExecIf("PJSIP/995-000204e2", "0?Set(HOTDESKCALL=1)") in new stack
61947[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:12] ExecIf("PJSIP/995-000204e2", "0?Set(CALLERID(name)=)") in new stack
61948[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("PJSIP/995-000204e2", "0?report") in new stack
61949[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("PJSIP/995-000204e2", "1?Set(REALCALLERIDNUM=995)") in new stack
61950[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:15] Set("PJSIP/995-000204e2", "AMPUSER=995") in new stack
61951[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:16] GotoIf("PJSIP/995-000204e2", "0?limit") in new stack
61952[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:17] Set("PJSIP/995-000204e2", "AMPUSERCIDNAME=PG") in new stack
61953[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:18] ExecIf("PJSIP/995-000204e2", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
61954[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:19] GotoIf("PJSIP/995-000204e2", "0?report") in new stack
61955[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:20] Set("PJSIP/995-000204e2", "AMPUSERCID=995") in new stack
61956[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:21] Set("PJSIP/995-000204e2", "__DIAL_OPTIONS=HhTtr") in new stack
61957[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:22] Set("PJSIP/995-000204e2", "CALLERID(all)="PG" <995>") in new stack
61958[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:23] ExecIf("PJSIP/995-000204e2", "0?Set(CUSDIAL=401)") in new stack
61959[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:24] ExecIf("PJSIP/995-000204e2", "0?Set(CALLERID(all)="PG" <995>)") in new stack
61960[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:25] GotoIf("PJSIP/995-000204e2", "0?limit") in new stack
61961[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:26] ExecIf("PJSIP/995-000204e2", "0?Set(GROUP(concurrency_limit)=995)") in new stack
61962[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:27] ExecIf("PJSIP/995-000204e2", "1?Set(CHANNEL(language)=de_DE)") in new stack
61963[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:28] NoOp("PJSIP/995-000204e2", "Macro Depth is 2") in new stack
61964[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:29] GotoIf("PJSIP/995-000204e2", "1?report2:macroerror") in new stack
61965[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (macro-user-callerid,s,30)
61966[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:30] GotoIf("PJSIP/995-000204e2", "0?continue") in new stack
61967[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:31] ExecIf("PJSIP/995-000204e2", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
61968[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:32] Set("PJSIP/995-000204e2", "__TTL=64") in new stack
61969[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:33] GotoIf("PJSIP/995-000204e2", "1?continue") in new stack
61970[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (macro-user-callerid,s,49)
61971[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:49] Set("PJSIP/995-000204e2", "CALLERID(number)=995") in new stack
61972[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:50] Set("PJSIP/995-000204e2", "CALLERID(name)=PG") in new stack
61973[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:51] GotoIf("PJSIP/995-000204e2", "0?cnum") in new stack
61974[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:52] Set("PJSIP/995-000204e2", "CDR(cnam)=PG") in new stack
61975[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:53] Set("PJSIP/995-000204e2", "CDR(cnum)=995") in new stack
61976[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-user-callerid:54] Set("PJSIP/995-000204e2", "CHANNEL(language)=de_DE") in new stack
61977[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:2] Set("PJSIP/995-000204e2", "RingGroupMethod=none") in new stack
61978[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:3] Set("PJSIP/995-000204e2", "__EXTTOCALL=401") in new stack
61979[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:4] Set("PJSIP/995-000204e2", "__PICKUPMARK=401") in new stack
61980[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:5] Set("PJSIP/995-000204e2", "RT=") in new stack
61981[2022-05-05 12:39:01] ERROR[17397][C-00002a3f] pbx_functions.c: Function SIP_HEADER not registered
61982[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:6] ExecIf("PJSIP/995-000204e2", "0?Macro(vm,novm,DIRECTDIAL,)") in new stack
61983[2022-05-05 12:39:01] ERROR[17397][C-00002a3f] pbx_functions.c: Function SIP_HEADER not registered
61984[2022-05-05 12:39:01] ERROR[17397][C-00002a3f] pbx_functions.c: Function SIP_HEADER not registered
61985[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:7] ExecIf("PJSIP/995-000204e2", "0?MacroExit()") in new stack
61986[2022-05-05 12:39:01] ERROR[17397][C-00002a3f] pbx_functions.c: Function SIP_HEADER not registered
61987[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:8] ExecIf("PJSIP/995-000204e2", "0?Macro(vm,novm,DIRECTDIAL,)") in new stack
61988[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:9] ExecIf("PJSIP/995-000204e2", "0?MacroExit()") in new stack
61989[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:10] Gosub("PJSIP/995-000204e2", "sub-record-check,s,1(exten,401,dontcare)") in new stack
61990[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/995-000204e2", "0?initialized") in new stack
61991[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/995-000204e2", "__REC_STATUS=INITIALIZED") in new stack
61992[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/995-000204e2", "NOW=1651747141") in new stack
61993[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/995-000204e2", "__DAY=05") in new stack
61994[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/995-000204e2", "__MONTH=05") in new stack
61995[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/995-000204e2", "__YEAR=2022") in new stack
61996[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/995-000204e2", "__TIMESTR=20220505-123901") in new stack
61997[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/995-000204e2", "__FROMEXTEN=995") in new stack
61998[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/995-000204e2", "__MON_FMT=wav") in new stack
61999[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/995-000204e2", "Recordings initialized") in new stack
62000[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/995-000204e2", "0?Set(ARG3=dontcare)") in new stack
62001[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/995-000204e2", "REC_POLICY_MODE_SAVE=") in new stack
62002[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/995-000204e2", "0?Set(REC_STATUS=NO)") in new stack
62003[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/995-000204e2", "5?checkaction") in new stack
62004[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (sub-record-check,s,17)
62005[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/995-000204e2", "1?sub-record-check,exten,1") in new stack
62006[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (sub-record-check,exten,1)
62007[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:1] NoOp("PJSIP/995-000204e2", "Exten Recording Check between 995 and 401") in new stack
62008[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:2] Set("PJSIP/995-000204e2", "CALLTYPE=internal") in new stack
62009[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:3] ExecIf("PJSIP/995-000204e2", "0?Set(CALLTYPE=)") in new stack
62010[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:4] Set("PJSIP/995-000204e2", "CALLEE=dontcare") in new stack
62011[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:5] ExecIf("PJSIP/995-000204e2", "0?Set(CALLEE=dontcare)") in new stack
62012[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:6] GotoIf("PJSIP/995-000204e2", "0?callee") in new stack
62013[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:7] GotoIf("PJSIP/995-000204e2", "1?caller") in new stack
62014[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (sub-record-check,exten,13)
62015[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:13] Set("PJSIP/995-000204e2", "RECMODE=dontcare") in new stack
62016[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:14] Set("PJSIP/995-000204e2", "CALLERRECMODE=dontcare") in new stack
62017[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:15] Set("PJSIP/995-000204e2", "CALEERECMODE=dontcare") in new stack
62018[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:16] GotoIf("PJSIP/995-000204e2", "0?processnormal") in new stack
62019[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:17] ExecIf("PJSIP/995-000204e2", "0?Set(RECMODE=dontcare)") in new stack
62020[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:18] ExecIf("PJSIP/995-000204e2", "0?Set(RECMODE=dontcare)") in new stack
62021[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:19] ExecIf("PJSIP/995-000204e2", "0?Set(RECMODE=dontcare)") in new stack
62022[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:20] ExecIf("PJSIP/995-000204e2", "0?Set(RECMODE=dontcare)") in new stack
62023[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:21] ExecIf("PJSIP/995-000204e2", "0?Set(RECMODE=dontcare)") in new stack
62024[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:22] ExecIf("PJSIP/995-000204e2", "1?Set(RECMODE=dontcare)") in new stack
62025[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:23] Gosub("PJSIP/995-000204e2", "recordcheck,1(dontcare,internal,401)") in new stack
62026[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/995-000204e2", "Starting recording check against dontcare") in new stack
62027[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/995-000204e2", "dontcare") in new stack
62028[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
62029[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/995-000204e2", "") in new stack
62030[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [exten@sub-record-check:24] Return("PJSIP/995-000204e2", "") in new stack
62031[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:11] GotoIf("PJSIP/995-000204e2", "1?macrodial") in new stack
62032[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (macro-exten-vm,s,17)
62033[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:17] GosubIf("PJSIP/995-000204e2", "0?clrheader,1()") in new stack
62034[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:18] Macro("PJSIP/995-000204e2", "dial-one,,HhTtr,401") in new stack
62035[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:1] Set("PJSIP/995-000204e2", "DEXTEN=401") in new stack
62036[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:2] ExecIf("PJSIP/995-000204e2", "0?Set(__EXTTOCALL=401)") in new stack
62037[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:3] Set("PJSIP/995-000204e2", "DIALSTATUS_CW=") in new stack
62038[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:4] GosubIf("PJSIP/995-000204e2", "0?screen,1()") in new stack
62039[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:5] GosubIf("PJSIP/995-000204e2", "0?cf,1()") in new stack
62040[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:6] GotoIf("PJSIP/995-000204e2", "1?skip1") in new stack
62041[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (macro-dial-one,s,9)
62042[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:9] GotoIf("PJSIP/995-000204e2", "0?nodial") in new stack
62043[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:10] GotoIf("PJSIP/995-000204e2", "0?continue") in new stack
62044[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:11] Set("PJSIP/995-000204e2", "EXTHASCW=ENABLED") in new stack
62045[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:12] GotoIf("PJSIP/995-000204e2", "0?next1:cwinusebusy") in new stack
62046[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (macro-dial-one,s,24)
62047[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:24] GotoIf("PJSIP/995-000204e2", "0?next3:continue") in new stack
62048[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (macro-dial-one,s,26)
62049[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:26] GotoIf("PJSIP/995-000204e2", "0?nodial") in new stack
62050[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:27] GosubIf("PJSIP/995-000204e2", "1?dstring,1():dlocal,1()") in new stack
62051[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:1] Set("PJSIP/995-000204e2", "DSTRING=") in new stack
62052[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:2] Set("PJSIP/995-000204e2", "DEVICES=401") in new stack
62053[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf("PJSIP/995-000204e2", "0?Return()") in new stack
62054[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf("PJSIP/995-000204e2", "0?Set(DEVICES=01)") in new stack
62055[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:5] Set("PJSIP/995-000204e2", "LOOPCNT=1") in new stack
62056[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:6] Set("PJSIP/995-000204e2", "ITER=1") in new stack
62057[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:7] Set("PJSIP/995-000204e2", "THISDIAL=PJSIP/401") in new stack
62058[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:8] GotoIf("PJSIP/995-000204e2", "0?docheck") in new stack
62059[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:9] NoOp("PJSIP/995-000204e2", "Debug: Found PJSIP Destination PJSIP/401") in new stack
62060[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:10] GotoIf("PJSIP/995-000204e2", "0?doset") in new stack
62061[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:11] NoOp("PJSIP/995-000204e2", "Debug: Updating PJSIP Destination with PJSIP_DIAL_CONTACTS") in new stack
62062[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:12] Set("PJSIP/995-000204e2", "THISDIAL=") in new stack
62063[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:13] ExecIf("PJSIP/995-000204e2", "1?Set(DIALSTATUS=CHANUNAVAIL)") in new stack
62064[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:14] GotoIf("PJSIP/995-000204e2", "1?skipset") in new stack
62065[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (macro-dial-one,dstring,16)
62066[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:16] Set("PJSIP/995-000204e2", "ITER=2") in new stack
62067[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:17] GotoIf("PJSIP/995-000204e2", "0?begin") in new stack
62068[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [dstring@macro-dial-one:18] ExecIf("PJSIP/995-000204e2", "1?Return()") in new stack
62069[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:28] GotoIf("PJSIP/995-000204e2", "1?nodial") in new stack
62070[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (macro-dial-one,s,60)
62071[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:60] NoOp("PJSIP/995-000204e2", "") in new stack
62072[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:61] ExecIf("PJSIP/995-000204e2", "0?Set(DIALSTATUS=NOANSWER)") in new stack
62073[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:62] NoOp("PJSIP/995-000204e2", "Returned from dial-one with nothing to call and DIALSTATUS: CHANUNAVAIL") in new stack
62074[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-dial-one:63] MacroExit("PJSIP/995-000204e2", "") in new stack
62075[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:19] Set("PJSIP/995-000204e2", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
62076[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:20] GosubIf("PJSIP/995-000204e2", "0?docfu,1()") in new stack
62077[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:21] GosubIf("PJSIP/995-000204e2", "0?docfb,1()") in new stack
62078[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:22] Set("PJSIP/995-000204e2", "DIALSTATUS=CHANUNAVAIL") in new stack
62079[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:23] ExecIf("PJSIP/995-000204e2", "0?MacroExit()") in new stack
62080[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-exten-vm:24] GotoIf("PJSIP/995-000204e2", "1?s-CHANUNAVAIL,1") in new stack
62081[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (macro-exten-vm,s-CHANUNAVAIL,1)
62082[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s-CHANUNAVAIL@macro-exten-vm:1] GotoIf("PJSIP/995-000204e2", "0?exit,1") in new stack
62083[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s-CHANUNAVAIL@macro-exten-vm:2] PlayTones("PJSIP/995-000204e2", "congestion") in new stack
62084[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s-CHANUNAVAIL@macro-exten-vm:3] Congestion("PJSIP/995-000204e2", "10") in new stack
62085[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] app_macro.c: Spawn extension (macro-exten-vm, s-CHANUNAVAIL, 3) exited non-zero on 'PJSIP/995-000204e2' in macro 'exten-vm'
62086[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Spawn extension (ext-local, 401, 3) exited non-zero on 'PJSIP/995-000204e2'
62087[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [h@ext-local:1] Macro("PJSIP/995-000204e2", "hangupcall,") in new stack
62088[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/995-000204e2", "1?theend") in new stack
62089[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx_builtins.c: Goto (macro-hangupcall,s,3)
62090[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/995-000204e2", "0?Set(CDR(recordingfile)=)") in new stack
62091[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Executing [s@macro-hangupcall:4] Hangup("PJSIP/995-000204e2", "") in new stack
62092[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/995-000204e2' in macro 'hangupcall'
62093[2022-05-05 12:39:01] VERBOSE[17397][C-00002a3f] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/995-000204e2'

Any idea how to debug this?

jgttgns · May 5, 2022, 11:29am

Can you post a complete SIP trace with pjsip set logger on? The current log messages basically end with Returned from dial-one with nothing to call and DIALSTATUS: CHANUNAVAIL, but I can’t see why there is no SIP account in the Dial() application.

david55 · May 5, 2022, 11:39am

It hasn’t reached the dial application. I would assume that there are no contacts registered for the target AOR.

Given the phones can call, I’d say they are configured with the correct authentication information, but haven’t been configured to register (or there are no contacts configured for the AOR).

pge · May 5, 2022, 11:50am

Hey guys!
Of course, here’s the output. Sorry for the mess - i tried to cut non-essential info:

64965Via: SIP/2.0/UDP 10.200.20.89:5060;rport=5060;received=10.200.20.89;branch=z9hG4bK925533580
64966Call-ID: [email protected]
64967From: "P.Geschke" <sip:[email protected]>;tag=845411864
64968To: <sip:[email protected]>;tag=0d26d248-9713-4502-9db2-bedb053f9cd2
64969CSeq: 131 INVITE
64970Server: FPBX-15.0.17.55(16.20.0)
64971Reason: Q.850;cause=34
64972Content-Length: 0
64973
64974



65046Via: SIP/2.0/UDP 10.200.20.5:5060;rport;branch=z9hG4bKPj828d10c7-d959-42ce-b1ef-da0f543b1ce7
65047From: <sip:[email protected]>;tag=921a9e17-723d-41c9-98eb-6109cf8bfeac
65048To: <sip:[email protected]>;tag=111880521
65049Contact: <sip:10.200.20.5:5060>
65050Call-ID: [email protected]
65051CSeq: 31029 NOTIFY
65052Event: dialog
65053Subscription-State: active;expires=462
65054Allow-Events: presence, dialog, message-summary, refer
65055Max-Forwards: 70
65056User-Agent: FPBX-15.0.17.55(16.20.0)
65057Content-Type: application/dialog-info+xml
65058Content-Length: 227
65059
65060<?xml version="1.0" encoding="UTF-8"?>
65061<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="7" state="full" entity="sip:[email protected]:5060">
65062 <dialog id="995">
65063 <state>confirmed</state>
65064 </dialog>
65065</dialog-info>
65066

65136[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP request (333 bytes) from UDP:10.200.20.89:5060 --->
65137ACK sip:[email protected] SIP/2.0
65138Via: SIP/2.0/UDP 10.200.20.89:5060;branch=z9hG4bK925533580;rport
65139Route: <sip:10.200.20.5:5060;lr>
65140From: "P.Geschke" <sip:[email protected]>;tag=845411864
65141To: <sip:[email protected]>;tag=0d26d248-9713-4502-9db2-bedb053f9cd2
65142Call-ID: [email protected]
65143CSeq: 131 ACK
65144Content-Length: 0
65145
65146
65147[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (503 bytes) from UDP:10.200.20.86:5060 --->
65148SIP/2.0 481 Subscription Does Not Exist
65149Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj828d10c7-d959-42ce-b1ef-da0f543b1ce7
65150From: <sip:[email protected]>;tag=921a9e17-723d-41c9-98eb-6109cf8bfeac
65151To: <sip:[email protected]>;tag=111880521
65152Call-ID: [email protected]
65153CSeq: 31029 NOTIFY
65154Supported: replaces, path, timer
65155User-Agent: Grandstream GXP2170 1.0.11.10
65156Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65157Content-Length: 0
65158
65159
65160[2022-05-05 13:31:26] VERBOSE[26748][C-00002a49] app_macro.c: Spawn extension (macro-exten-vm, s-CHANUNAVAIL, 3) exited non-zero on 'PJSIP/995-000204f8' in macro 'exten-vm'
65161[2022-05-05 13:31:26] VERBOSE[26748][C-00002a49] pbx.c: Spawn extension (ext-local, 401, 3) exited non-zero on 'PJSIP/995-000204f8'
65162[2022-05-05 13:31:26] VERBOSE[26748][C-00002a49] pbx.c: Executing [h@ext-local:1] Macro("PJSIP/995-000204f8", "hangupcall,") in new stack
65163[2022-05-05 13:31:26] VERBOSE[26748][C-00002a49] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/995-000204f8", "1?theend") in new stack
65164[2022-05-05 13:31:26] VERBOSE[26748][C-00002a49] pbx_builtins.c: Goto (macro-hangupcall,s,3)
65165[2022-05-05 13:31:26] VERBOSE[26748][C-00002a49] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/995-000204f8", "0?Set(CDR(recordingfile)=)") in new stack
65166[2022-05-05 13:31:26] VERBOSE[26748][C-00002a49] pbx.c: Executing [s@macro-hangupcall:4] Hangup("PJSIP/995-000204f8", "") in new stack
65167[2022-05-05 13:31:26] VERBOSE[26748][C-00002a49] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/995-000204f8' in macro 'hangupcall'
65168[2022-05-05 13:31:26] VERBOSE[26748][C-00002a49] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'PJSIP/995-000204f8'
65169[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (517 bytes) from UDP:10.200.20.66:5060 --->
65170SIP/2.0 200 OK
65171Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj8c76b5a5-e7df-4d49-8c51-44796eb3239e
65172From: <sip:[email protected]>;tag=a0c0fd3c-f2c7-4f8c-8c95-8599ce88d9bd
65173To: <sip:[email protected]>;tag=412564463
65174Call-ID: [email protected]
65175CSeq: 22242 NOTIFY
65176Contact: <sip:[email protected]:5060>
65177Supported: replaces, path, timer
65178User-Agent: Grandstream GXP2170 1.0.11.10
65179Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65180Content-Length: 0
65181
65182
65183[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (516 bytes) from UDP:10.200.20.77:5060 --->
65184SIP/2.0 200 OK
65185Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj2ce254f3-9617-4f8a-a7e6-c46e663fb981
65186From: <sip:[email protected]>;tag=843c6509-d334-41f3-9029-a0ff336b319b
65187To: <sip:[email protected]>;tag=1571180409
65188Call-ID: [email protected]
65189CSeq: 31246 NOTIFY
65190Contact: <sip:[email protected]:5060>
65191Supported: replaces, path, timer
65192User-Agent: Grandstream GXP2170 1.0.11.16
65193Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65194Content-Length: 0
65195
65196
65197[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (515 bytes) from UDP:10.200.20.69:5060 --->
65198SIP/2.0 200 OK
65199Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj35f5ca02-be44-42ac-b8cf-25a57b5a2d97
65200From: <sip:[email protected]>;tag=87e7f231-53ec-4834-b423-49b5548ad63d
65201To: <sip:[email protected]>;tag=1734990484
65202Call-ID: [email protected]
65203CSeq: 22997 NOTIFY
65204Contact: <sip:[email protected]:5060>
65205Supported: replaces, path, timer
65206User-Agent: Grandstream GXP2170 1.0.11.16
65207Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65208Content-Length: 0
65209
65210
65211[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (516 bytes) from UDP:10.200.20.73:5060 --->
65212SIP/2.0 200 OK
65213Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj56bceb30-39d2-42fb-a68f-46bf06f4feda
65214From: <sip:[email protected]>;tag=e9f4bf83-8944-479d-80a2-9826c630eae1
65215To: <sip:[email protected]>;tag=698966246
65216Call-ID: [email protected]
65217CSeq: 15792 NOTIFY
65218Contact: <sip:[email protected]:5060>
65219Supported: replaces, path, timer
65220User-Agent: Grandstream GXP2170 1.0.11.16
65221Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65222Content-Length: 0
65223
65224
65225[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (515 bytes) from UDP:10.200.20.72:5060 --->
65226SIP/2.0 200 OK
65227Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj0ab4275e-7618-4631-b964-a008783213d5
65228From: <sip:[email protected]>;tag=649153c3-d76e-44ba-9b70-110ff89655f7
65229To: <sip:[email protected]>;tag=317402124
65230Call-ID: [email protected]
65231CSeq: 620 NOTIFY
65232Contact: <sip:[email protected]:5060>
65233Supported: replaces, path, timer
65234User-Agent: Grandstream GXP2170 1.0.11.10
65235Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65236Content-Length: 0
65237
65238
65239[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (515 bytes) from UDP:10.200.20.86:5060 --->
65240SIP/2.0 200 OK
65241Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj2200206d-f669-4254-a614-05d9ed2eef74
65242From: <sip:[email protected]>;tag=e1671ee3-ff95-4a35-9c0e-d6a98e0087da
65243To: <sip:[email protected]>;tag=52924324
65244Call-ID: [email protected]
65245CSeq: 2718 NOTIFY
65246Contact: <sip:[email protected]:5060>
65247Supported: replaces, path, timer
65248User-Agent: Grandstream GXP2170 1.0.11.10
65249Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65250Content-Length: 0
65251
65252

65299[2022-05-05 13:31:26] VERBOSE[29763] res_pjsip_logger.c: <--- Transmitting SIP request (809 bytes) to UDP:10.200.20.77:5060 --->
65300NOTIFY sip:[email protected]:5060 SIP/2.0
65301Via: SIP/2.0/UDP 10.200.20.5:5060;rport;branch=z9hG4bKPj495316fa-79fb-4e0c-b1d4-ac48300ea87a
65302From: <sip:[email protected]>;tag=843c6509-d334-41f3-9029-a0ff336b319b
65303To: <sip:[email protected]>;tag=1571180409
65304Contact: <sip:10.200.20.5:5060>
65305Call-ID: [email protected]
65306CSeq: 31247 NOTIFY
65307Event: dialog
65308Subscription-State: active;expires=1964
65309Allow-Events: presence, dialog, message-summary, refer
65310Max-Forwards: 70
65311User-Agent: FPBX-15.0.17.55(16.20.0)
65312Content-Type: application/dialog-info+xml
65313Content-Length: 230
65314
65315<?xml version="1.0" encoding="UTF-8"?>
65316<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="336" state="full" entity="sip:[email protected]:5060">
65317 <dialog id="995">
65318 <state>terminated</state>
65319 </dialog>
65320</dialog-info>
65321
65322[2022-05-05 13:31:26] VERBOSE[27961] res_pjsip_logger.c: <--- Transmitting SIP request (806 bytes) to UDP:10.200.20.72:5060 --->
65323NOTIFY sip:[email protected]:5060 SIP/2.0
65324Via: SIP/2.0/UDP 10.200.20.5:5060;rport;branch=z9hG4bKPjed28f437-84a9-41e8-bea9-a10ab343407a
65325From: <sip:[email protected]>;tag=649153c3-d76e-44ba-9b70-110ff89655f7
65326To: <sip:[email protected]>;tag=317402124
65327Contact: <sip:10.200.20.5:5060>
65328Call-ID: [email protected]
65329CSeq: 621 NOTIFY
65330Event: dialog
65331Subscription-State: active;expires=1333
65332Allow-Events: presence, dialog, message-summary, refer
65333Max-Forwards: 70
65334User-Agent: FPBX-15.0.17.55(16.20.0)
65335Content-Type: application/dialog-info+xml
65336Content-Length: 228
65337
65338<?xml version="1.0" encoding="UTF-8"?>
65339<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="8" state="full" entity="sip:[email protected]:5060">
65340 <dialog id="995">
65341 <state>terminated</state>
65342 </dialog>
65343</dialog-info>
65344

65391[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (515 bytes) from UDP:10.200.20.69:5060 --->
65392SIP/2.0 200 OK
65393Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj67948785-b4fa-4ac3-b623-3d5a2bd1b7d8
65394From: <sip:[email protected]>;tag=87e7f231-53ec-4834-b423-49b5548ad63d
65395To: <sip:[email protected]>;tag=1734990484
65396Call-ID: [email protected]
65397CSeq: 22998 NOTIFY
65398Contact: <sip:[email protected]:5060>
65399Supported: replaces, path, timer
65400User-Agent: Grandstream GXP2170 1.0.11.16
65401Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65402Content-Length: 0
65403
65404
65405[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (516 bytes) from UDP:10.200.20.73:5060 --->
65406SIP/2.0 200 OK
65407Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPje8b61f47-251a-4bc6-bd9f-46036b3118bb
65408From: <sip:[email protected]>;tag=e9f4bf83-8944-479d-80a2-9826c630eae1
65409To: <sip:[email protected]>;tag=698966246
65410Call-ID: [email protected]
65411CSeq: 15793 NOTIFY
65412Contact: <sip:[email protected]:5060>
65413Supported: replaces, path, timer
65414User-Agent: Grandstream GXP2170 1.0.11.16
65415Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65416Content-Length: 0
65417
65418
65419[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (516 bytes) from UDP:10.200.20.77:5060 --->
65420SIP/2.0 200 OK
65421Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj495316fa-79fb-4e0c-b1d4-ac48300ea87a
65422From: <sip:[email protected]>;tag=843c6509-d334-41f3-9029-a0ff336b319b
65423To: <sip:[email protected]>;tag=1571180409
65424Call-ID: [email protected]
65425CSeq: 31247 NOTIFY
65426Contact: <sip:[email protected]:5060>
65427Supported: replaces, path, timer
65428User-Agent: Grandstream GXP2170 1.0.11.16
65429Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65430Content-Length: 0
65431
65432
65433[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (517 bytes) from UDP:10.200.20.66:5060 --->
65434SIP/2.0 200 OK
65435Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj3878e83a-4f75-4764-987e-fea4875629a7
65436From: <sip:[email protected]>;tag=a0c0fd3c-f2c7-4f8c-8c95-8599ce88d9bd
65437To: <sip:[email protected]>;tag=412564463
65438Call-ID: [email protected]
65439CSeq: 22243 NOTIFY
65440Contact: <sip:[email protected]:5060>
65441Supported: replaces, path, timer
65442User-Agent: Grandstream GXP2170 1.0.11.10
65443Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65444Content-Length: 0
65445
65446
65447[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (515 bytes) from UDP:10.200.20.86:5060 --->
65448SIP/2.0 200 OK
65449Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj6d7fe1d7-5f36-40ab-97f0-1ad97559c45f
65450From: <sip:[email protected]>;tag=e1671ee3-ff95-4a35-9c0e-d6a98e0087da
65451To: <sip:[email protected]>;tag=52924324
65452Call-ID: [email protected]
65453CSeq: 2719 NOTIFY
65454Contact: <sip:[email protected]:5060>
65455Supported: replaces, path, timer
65456User-Agent: Grandstream GXP2170 1.0.11.10
65457Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65458Content-Length: 0
65459
65460
65461[2022-05-05 13:31:26] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (515 bytes) from UDP:10.200.20.72:5060 --->
65462SIP/2.0 200 OK
65463Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPjed28f437-84a9-41e8-bea9-a10ab343407a
65464From: <sip:[email protected]>;tag=649153c3-d76e-44ba-9b70-110ff89655f7
65465To: <sip:[email protected]>;tag=317402124
65466Call-ID: [email protected]
65467CSeq: 621 NOTIFY
65468Contact: <sip:[email protected]:5060>
65469Supported: replaces, path, timer
65470User-Agent: Grandstream GXP2170 1.0.11.10
65471Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65472Content-Length: 0
65473
65474

65578[2022-05-05 13:31:31] VERBOSE[2285] res_pjsip_logger.c: <--- Transmitting SIP request (418 bytes) to UDP:10.200.20.89:5060 --->
65579OPTIONS sip:[email protected]:5060 SIP/2.0
65580Via: SIP/2.0/UDP 10.200.20.5:5060;rport;branch=z9hG4bKPj23191185-2092-4d53-ab6c-b4e65f292aca
65581From: <sip:[email protected]>;tag=a2e25b54-fc59-4279-bc29-e2ce2a245b7d
65582To: <sip:[email protected]>
65583Contact: <sip:[email protected]:5060>
65584Call-ID: 93b59882-e7d8-41c3-afb6-586310be37a3
65585CSeq: 61248 OPTIONS
65586Max-Forwards: 70
65587User-Agent: FPBX-15.0.17.55(16.20.0)
65588Content-Length: 0
65589
65590
65591[2022-05-05 13:31:31] VERBOSE[2285] res_pjsip_logger.c: <--- Transmitting SIP request (497 bytes) to TCP:159.65.186.176:26505 --->
65592OPTIONS sip:[email protected]:26505;transport=TCP;rinstance=18954785 SIP/2.0
65593Via: SIP/2.0/TCP 212.95.115.1:5060;rport;branch=z9hG4bKPj8f7b4b8c-56bc-40c2-955c-d24024bde970;alias
65594From: <sip:[email protected]>;tag=8db2cac4-4d8b-4130-99ad-a0dbf1f7ce21
65595To: <sip:[email protected];rinstance=18954785>
65596Contact: <sip:[email protected]:5060;transport=TCP>
65597Call-ID: 396689fa-83b0-4314-b8c3-ae0f390d67cd
65598CSeq: 56898 OPTIONS
65599Max-Forwards: 70
65600User-Agent: FPBX-15.0.17.55(16.20.0)
65601Content-Length: 0
65602
65603
65604[2022-05-05 13:31:31] VERBOSE[2285] res_pjsip_logger.c: <--- Transmitting SIP request (497 bytes) to TCP:159.65.186.176:28259 --->
65605OPTIONS sip:[email protected]:28259;transport=TCP;rinstance=CEA3A328 SIP/2.0
65606Via: SIP/2.0/TCP 212.95.115.1:5060;rport;branch=z9hG4bKPj9f19c450-0843-4c09-82f4-5318ff04e28e;alias
65607From: <sip:[email protected]>;tag=4a98d80d-945e-45be-839a-c9ff21d77bcb
65608To: <sip:[email protected];rinstance=CEA3A328>
65609Contact: <sip:[email protected]:5060;transport=TCP>
65610Call-ID: a4b65674-5a96-428a-a212-5e351da71981
65611CSeq: 56000 OPTIONS
65612Max-Forwards: 70
65613User-Agent: FPBX-15.0.17.55(16.20.0)
65614Content-Length: 0
65615
65616
65617[2022-05-05 13:31:31] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (485 bytes) from UDP:10.200.20.89:5060 --->
65618SIP/2.0 200 OK
65619Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj23191185-2092-4d53-ab6c-b4e65f292aca
65620From: <sip:[email protected]>;tag=a2e25b54-fc59-4279-bc29-e2ce2a245b7d
65621To: <sip:[email protected]>;tag=1931888273
65622Call-ID: 93b59882-e7d8-41c3-afb6-586310be37a3
65623CSeq: 61248 OPTIONS
65624Supported: replaces, path, timer
65625User-Agent: Grandstream GXP2170 1.0.11.10
65626Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
65627Content-Length: 0
65628
65629
65630[2022-05-05 13:31:31] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (545 bytes) from TCP:159.65.186.176:26505 --->
65631SIP/2.0 200 OK
65632Via: SIP/2.0/TCP 212.95.115.1:5060;rport=5060;branch=z9hG4bKPj8f7b4b8c-56bc-40c2-955c-d24024bde970;alias;received=212.95.115.1
65633Contact: <sip:[email protected]:26505;transport=tcp>
65634From: <sip:[email protected]>;tag=8db2cac4-4d8b-4130-99ad-a0dbf1f7ce21
65635Call-ID: 396689fa-83b0-4314-b8c3-ae0f390d67cd
65636CSeq: 56898 OPTIONS
65637To: <sip:[email protected];rinstance=18954785>
65638Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
65639Supported: replaces, path
65640Accept: application/sdp
65641User-Agent: Acrobits SIPIS
65642Content-Length: 0
65643
65644
65645[2022-05-05 13:31:31] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (545 bytes) from TCP:159.65.186.176:28259 --->
65646SIP/2.0 200 OK
65647Via: SIP/2.0/TCP 212.95.115.1:5060;rport=5060;branch=z9hG4bKPj9f19c450-0843-4c09-82f4-5318ff04e28e;alias;received=212.95.115.1
65648Contact: <sip:[email protected]:28259;transport=tcp>
65649From: <sip:[email protected]>;tag=4a98d80d-945e-45be-839a-c9ff21d77bcb
65650Call-ID: a4b65674-5a96-428a-a212-5e351da71981
65651CSeq: 56000 OPTIONS
65652To: <sip:[email protected];rinstance=CEA3A328>
65653Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
65654Supported: replaces, path
65655Accept: application/sdp
65656User-Agent: Acrobits SIPIS
65657Content-Length: 0
65658
65659


66058
66059
66060[2022-05-05 13:31:45] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP request (531 bytes) from TCP:10.200.20.90:2056 --->
66061SUBSCRIBE sip:10.200.20.5:5060;transport=TCP SIP/2.0
66062Via: SIP/2.0/TCP 10.200.20.90:5060;branch=z9hG4bK-C00BB341;rport
66063From: <sip:[email protected]>;tag=488043032
66064To: <sip:[email protected];user=phone>;tag=7c4d861a-4570-4287-b9f9-f1ce247c4998
66065Call-ID: fc0ba524a8736201f8a60090334f60a2@C
66066CSeq: 2144 SUBSCRIBE
66067Contact: <sip:[email protected]:5060;transport=TCP>
66068Accept: application/dialog-info+xml
66069Content-Length: 0
66070Expires: 30
66071Max-Forwards: 70
66072User-Agent: (innovaphone IP111A/13r1 sr26 [13.2940/132523/1300])
66073Event: dialog
66074
66075
66076[2022-05-05 13:31:45] VERBOSE[12596] res_pjsip_logger.c: <--- Transmitting SIP response (573 bytes) to TCP:10.200.20.90:2056 --->
66077SIP/2.0 200 OK
66078Via: SIP/2.0/TCP 10.200.20.90:5060;rport=2056;received=10.200.20.90;branch=z9hG4bK-C00BB341
66079Call-ID: fc0ba524a8736201f8a60090334f60a2@C
66080From: <sip:[email protected]>;tag=488043032
66081To: <sip:[email protected];user=phone>;tag=7c4d861a-4570-4287-b9f9-f1ce247c4998
66082CSeq: 2144 SUBSCRIBE
66083Expires: 30
66084Contact: <sip:10.200.20.5:5060;transport=TCP>
66085Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
66086Supported: 100rel, timer, replaces, norefersub
66087Server: FPBX-15.0.17.55(16.20.0)
66088Content-Length: 0
66089
66090
66091[2022-05-05 13:31:45] VERBOSE[12596] res_pjsip_logger.c: <--- Transmitting SIP request (867 bytes) to TCP:10.200.20.90:2056 --->
66092NOTIFY sip:[email protected]:2056;transport=TCP SIP/2.0
66093Via: SIP/2.0/TCP 10.200.20.5:5060;rport;branch=z9hG4bKPj724f542c-17b5-400a-8250-aa5ac4f48988;alias
66094From: <sip:[email protected];user=phone>;tag=7c4d861a-4570-4287-b9f9-f1ce247c4998
66095To: <sip:[email protected]>;tag=488043032
66096Contact: <sip:10.200.20.5:5060;transport=TCP>
66097Call-ID: fc0ba524a8736201f8a60090334f60a2@C
66098CSeq: 27645 NOTIFY
66099Event: dialog
66100Subscription-State: active;expires=30
66101Allow-Events: presence, dialog, message-summary, refer
66102Max-Forwards: 70
66103User-Agent: FPBX-15.0.17.55(16.20.0)
66104Content-Type: application/dialog-info+xml
66105Content-Length: 243
66106
66107<?xml version="1.0" encoding="UTF-8"?>
66108<dialog-info xmlns="urn:ietf:params:xml:ns:dialog-info" version="18" state="full" entity="sip:[email protected]:5060;transport=TCP">
66109 <dialog id="401">
66110 <state>terminated</state>
66111 </dialog>
66112</dialog-info>
66113
66114[2022-05-05 13:31:45] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (412 bytes) from TCP:10.200.20.90:2056 --->
66115SIP/2.0 200 OK
66116Via: SIP/2.0/TCP 10.200.20.5:5060;rport=5060;received=10.200.20.5;branch=z9hG4bKPj724f542c-17b5-400a-8250-aa5ac4f48988;alias
66117From: <sip:[email protected];user=phone>;tag=7c4d861a-4570-4287-b9f9-f1ce247c4998
66118To: <sip:[email protected]>;tag=488043032
66119Call-ID: fc0ba524a8736201f8a60090334f60a2@C
66120CSeq: 27645 NOTIFY
66121Content-Length: 0
66122Server: (innovaphone IP111A/13r1 sr26 [13.2940/132523/1300])
66123
66124
66125[2022-05-05 13:31:45] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP request (526 bytes) from TCP:10.200.20.90:2056 --->
66126SUBSCRIBE sip:10.200.20.5:5060;transport=TCP SIP/2.0
66127Via: SIP/2.0/TCP 10.200.20.90:5060;branch=z9hG4bK-C00BB342;rport
66128From: <sip:[email protected]>;tag=488043031
66129To: <sip:[email protected];user=phone>;tag=9cd8f71f-d9a2-4a99-a2bc-82fe2c7d72f9
66130Call-ID: 3956a124a8736201f6a60090334f60a2@B
66131CSeq: 2144 SUBSCRIBE
66132Contact: <sip:[email protected]:5060;transport=TCP>
66133Accept: application/pidf+xml
66134Content-Length: 0
66135Expires: 30
66136Max-Forwards: 70
66137User-Agent: (innovaphone IP111A/13r1 sr26 [13.2940/132523/1300])
66138Event: presence
66139
66140
66141[2022-05-05 13:31:45] VERBOSE[4773] res_pjsip_logger.c: <--- Transmitting SIP response (573 bytes) to TCP:10.200.20.90:2056 --->
66142SIP/2.0 200 OK
66143Via: SIP/2.0/TCP 10.200.20.90:5060;rport=2056;received=10.200.20.90;branch=z9hG4bK-C00BB342
66144Call-ID: 3956a124a8736201f6a60090334f60a2@B
66145From: <sip:[email protected]>;tag=488043031
66146To: <sip:[email protected];user=phone>;tag=9cd8f71f-d9a2-4a99-a2bc-82fe2c7d72f9
66147CSeq: 2144 SUBSCRIBE
66148Expires: 30
66149Contact: <sip:10.200.20.5:5060;transport=TCP>
66150Allow: OPTIONS, REGISTER, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, MESSAGE, REFER
66151Supported: 100rel, timer, replaces, norefersub
66152Server: FPBX-15.0.17.55(16.20.0)
66153Content-Length: 0
66154
66155
66156[2022-05-05 13:31:45] VERBOSE[4773] res_pjsip_logger.c: <--- Transmitting SIP request (1032 bytes) to TCP:10.200.20.90:2056 --->
66157NOTIFY sip:[email protected]:2056;transport=TCP SIP/2.0
66158Via: SIP/2.0/TCP 10.200.20.5:5060;rport;branch=z9hG4bKPj0d859b79-79ef-42a5-8fdd-c7fd74c58715;alias
66159From: <sip:[email protected];user=phone>;tag=9cd8f71f-d9a2-4a99-a2bc-82fe2c7d72f9
66160To: <sip:[email protected]>;tag=488043031
66161Contact: <sip:10.200.20.5:5060;transport=TCP>
66162Call-ID: 3956a124a8736201f6a60090334f60a2@B
66163CSeq: 11702 NOTIFY
66164Event: presence
66165Subscription-State: active;expires=29
66166Allow-Events: presence, dialog, message-summary, refer
66167Max-Forwards: 70
66168User-Agent: FPBX-15.0.17.55(16.20.0)
66169Content-Type: application/pidf+xml
66170Content-Length: 413
66171
66172<?xml version="1.0" encoding="UTF-8"?>
66173<presence entity="sip:[email protected]:5060;transport=TCP" xmlns="urn:ietf:params:xml:ns:pidf" xmlns:dm="urn:ietf:params:xml:ns:pidf:data-model" xmlns:rpid="urn:ietf:params:xml:ns:pidf:rpid">
66174 <note>Unavailable</note>
66175 <tuple id="401">
66176 <status>
66177 <basic>closed</basic>
66178 </status>
66179 <contact priority="1">sip:[email protected]</contact>
66180 </tuple>
66181 <dm:person />
66182</presence>
66183
66184[2022-05-05 13:31:45] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP response (412 bytes) from TCP:10.200.20.90:2056 --->
66185SIP/2.0 200 OK
66186Via: SIP/2.0/TCP 10.200.20.5:5060;rport=5060;received=10.200.20.5;branch=z9hG4bKPj0d859b79-79ef-42a5-8fdd-c7fd74c58715;alias
66187From: <sip:[email protected];user=phone>;tag=9cd8f71f-d9a2-4a99-a2bc-82fe2c7d72f9
66188To: <sip:[email protected]>;tag=488043031
66189Call-ID: 3956a124a8736201f6a60090334f60a2@B
66190CSeq: 11702 NOTIFY
66191Content-Length: 0
66192Server: (innovaphone IP111A/13r1 sr26 [13.2940/132523/1300])
66193
66194

66221[2022-05-05 13:31:48] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP request (752 bytes) from TCP:10.200.20.90:2056 --->
66222REGISTER sip:10.200.20.5 SIP/2.0
66223Authorization: Digest username="401",realm="asterisk",nonce="1651750260/4ea8bcd5ae23048da42e7f0eb95b689e",response="a1aa01188acf3d10c2d650f28900e9b7",uri="sip:10.200.20.5",qop=auth,cnonce="005c591c810870cc",nc=00000002,opaque="47a061e3508ec352",algorithm=MD5
66224Via: SIP/2.0/TCP 10.200.20.90:5060;branch=z9hG4bK-C00BB343;rport
66225From: <sip:[email protected]>;tag=488043113
66226To: <sip:[email protected]>
66227Call-ID: 5f93971aa8736201f1a60090334f60a2
66228CSeq: 1146 REGISTER
66229Contact: <sip:[email protected]:5060;transport=TCP>;expires=15
66230Accept: innovaphone/data
66231Content-Length: 0
66232Expires: 15
66233Max-Forwards: 70
66234User-Agent: (innovaphone IP111A/13r1 sr26 [13.2940/132523/1300])
66235Allow-Events: reg,dialog,message-summary,presence
66236
66237
66238[2022-05-05 13:31:48] VERBOSE[22193] res_pjsip_logger.c: <--- Transmitting SIP response (487 bytes) to TCP:10.200.20.90:2056 --->
66239SIP/2.0 401 Unauthorized
66240Via: SIP/2.0/TCP 10.200.20.90:5060;rport=2056;received=10.200.20.90;branch=z9hG4bK-C00BB343
66241Call-ID: 5f93971aa8736201f1a60090334f60a2
66242From: <sip:[email protected]>;tag=488043113
66243To: <sip:[email protected]>;tag=z9hG4bK-C00BB343
66244CSeq: 1146 REGISTER
66245WWW-Authenticate: Digest realm="asterisk",nonce="1651750308/e6dcc836ac2c32079391cff973897d8d",opaque="0522d36975ee0e19",stale=true,algorithm=md5,qop="auth"
66246Server: FPBX-15.0.17.55(16.20.0)
66247Content-Length: 0
66248
66249
66250[2022-05-05 13:31:48] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP request (752 bytes) from TCP:10.200.20.90:2056 --->
66251REGISTER sip:10.200.20.5 SIP/2.0
66252Authorization: Digest username="401",realm="asterisk",nonce="1651750308/e6dcc836ac2c32079391cff973897d8d",response="6d2cef45eab582bed861bb570ce33e20",uri="sip:10.200.20.5",qop=auth,cnonce="005c591c810870cc",nc=00000001,opaque="0522d36975ee0e19",algorithm=MD5
66253Via: SIP/2.0/TCP 10.200.20.90:5060;branch=z9hG4bK-C00BB344;rport
66254From: <sip:[email protected]>;tag=488043113
66255To: <sip:[email protected]>
66256Call-ID: 5f93971aa8736201f1a60090334f60a2
66257CSeq: 1147 REGISTER
66258Contact: <sip:[email protected]:5060;transport=TCP>;expires=15
66259Accept: innovaphone/data
66260Content-Length: 0
66261Expires: 15
66262Max-Forwards: 70
66263User-Agent: (innovaphone IP111A/13r1 sr26 [13.2940/132523/1300])
66264Allow-Events: reg,dialog,message-summary,presence
66265
66266
66267[2022-05-05 13:31:48] VERBOSE[25315] res_pjsip_logger.c: <--- Transmitting SIP response (433 bytes) to TCP:10.200.20.90:2056 --->
66268SIP/2.0 200 OK
66269Via: SIP/2.0/TCP 10.200.20.90:5060;rport=2056;received=10.200.20.90;branch=z9hG4bK-C00BB344
66270Call-ID: 5f93971aa8736201f1a60090334f60a2
66271From: <sip:[email protected]>;tag=488043113
66272To: <sip:[email protected]>;tag=z9hG4bK-C00BB344
66273CSeq: 1147 REGISTER
66274Date: Thu, 05 May 2022 11:31:48 GMT
66275Contact: <sip:[email protected]:2056;transport=TCP>;expires=59
66276Expires: 60
66277Server: FPBX-15.0.17.55(16.20.0)
66278Content-Length: 0
66279
66280
66296
66297[2022-05-05 13:31:50] VERBOSE[15893] res_pjsip_logger.c: <--- Transmitting SIP response (613 bytes) to TCP:159.65.251.173:15811 --->
66298SIP/2.0 401 Unauthorized
66299Via: SIP/2.0/TCP 10.65.5.3:15811;rport=15811;received=159.65.251.173;branch=z9hG4bK6IUzGG5o8CMX6VgH
66300Call-ID: 865BED38AE1735C78863A5666316D0B8B8C9CCE9
66301From: <sip:[email protected]>;tag=353B034D23735B4AD9540699BAD5DA11
66302To: <sip:[email protected]>;tag=z9hG4bK6IUzGG5o8CMX6VgH
66303CSeq: 21659 REGISTER
66304WWW-Authenticate: Digest realm="asterisk",nonce="1651750310/5a7ced581a0ec4c5b74ee9d25e02a246",opaque="583897451667d035",algorithm=md5,qop="auth"
66305Server: FPBX-15.0.17.55(16.20.0)
66306Content-Length: 0
66307
66308

pge · May 5, 2022, 12:00pm

Hey david! The phone has a created extension to which it (as i assume) seems to be registered.
However it shows up as OFFLINE on Asterisk Info:

2022-05-05_14-00

david55 · May 5, 2022, 12:25pm

The phone is offering a registration timeout of 15 seconds. That is exceedingly short. It is less than the time to complete a normal retransmission sequence if the first attempt gets lost.

Asterisk appears to be increasing that to 59 seconds, which is still rather short, and, in any case, its only choices are to reject the registration, or reduce the expiry, neither of which it is doing. It looks to me as though you have a combination of an unreasonable registration interval in the phone and a bug in chan_pjsip in its handling of short registration intervals The phone may have accepted the increased interval and Asterisk may be using the original one, or Asterisk may have assumed that it rejected the short interval even though it has told the phone it has accepted something.

Give it a few hours in case someone is able to challenge my reasoning, then raise a bug at issues.asterisk.org. In the mean time, if possible, set the phone’s re-registration interval to at least 60 second.

     The registrar MAY choose an expiration less than the requested
     expiration interval.  If and only if the requested expiration
     interval is greater than zero AND smaller than one hour AND
     less than a registrar-configured minimum, the registrar MAY
     reject the registration with a response of 423 (Interval Too
     Brief).  This response MUST contain a Min-Expires header field
     that states the minimum expiration interval the registrar is
     willing to honor.  It then skips the remaining steps.

jgttgns · May 5, 2022, 2:54pm

A couple of things look pretty strange here. It seems as if you are doing only calls within a LAN segment, so I wonder why you need a STUN server and an explicit rport of 2056. Also, some contact headers seem to be incomplete, but I don’t know why this is happening.

What do you get if for the moment you forget about the encryption stuff and configure the extension inside FPBX with default values?

david55 · May 5, 2022, 3:00pm

That’s the expected behaviour when the request comes from port 2056 and has rport set on the Via header.

jgttgns · May 5, 2022, 4:05pm

Sure, but why is this needed in this situation?

pge · May 5, 2022, 5:03pm

Thanks david!
I have increased the timeout to 90 seconds, but still no joy. (Also tried 180,300)
I deavtivate and re-activeate the account on the phone and try ringing it - the call dialogue disappears immediately.

pge · May 5, 2022, 5:03pm

Agreed. Setting STUN had no use here, since this is inside a LAN.
Removed the server, still no luck placing a call to the account.

pge · May 5, 2022, 5:21pm

The phone itself also claims to be registered.

pge · May 5, 2022, 5:46pm

This really puzzles me…

		
1034728	[2022-05-05 19:38:50] VERBOSE[20535] res_pjsip_logger.c: <--- Received SIP request (754 bytes) from TCP:10.200.20.90:2111 --->	
1034729	REGISTER sip:10.200.20.5 SIP/2.0	
1034730	Authorization: Digest username="401",realm="asterisk",nonce="1651772182/53f0844fea3ae38f7ee82d34bfd679db",response="f978c0cdcb2356552ecbf27f9b5479e7",uri="sip:10.200.20.5",qop=auth,cnonce="0b749bee810870cc",nc=00000002,opaque="2705975b1aed3dbe",algorithm=MD5	
1034731	Via: SIP/2.0/TCP 10.200.20.90:5060;branch=z9hG4bK-C00BBD49;rport	
1034732	From: <sip:[email protected]>;tag=488043562	
1034733	To: <sip:[email protected]>	
1034734	Call-ID: 9e3b7ffd0274620141ab0090334f60a2	
1034735	CSeq: 1030 REGISTER	
1034736	Contact: <sip:[email protected]:5060;transport=TCP>;expires=300	
1034737	Accept: innovaphone/data	
1034738	Content-Length: 0	
1034739	Expires: 300	
1034740	Max-Forwards: 70	
1034741	User-Agent: (innovaphone IP111A/13r1 sr26 [13.2940/132523/1300])	
1034742	Allow-Events: reg,dialog,message-summary,presence	
1034743		
1034744		
1034745	[2022-05-05 19:38:50] VERBOSE[8882] res_pjsip_logger.c: <--- Transmitting SIP response (487 bytes) to TCP:10.200.20.90:2111 --->	
1034746	SIP/2.0 401 Unauthorized	
1034747	Via: SIP/2.0/TCP 10.200.20.90:5060;rport=2111;received=10.200.20.90;branch=z9hG4bK-C00BBD49	
1034748	Call-ID: 9e3b7ffd0274620141ab0090334f60a2	
1034749	From: <sip:[email protected]>;tag=488043562	
1034750	To: <sip:[email protected]>;tag=z9hG4bK-C00BBD49	
1034751	CSeq: 1030 REGISTER	
1034752	WWW-Authenticate: Digest realm="asterisk",nonce="1651772330/a6080b26f6aff2203747d1626e76c9e0",opaque="1a8a46e42932740c",stale=true,algorithm=md5,qop="auth"	
1034753	Server: FPBX-15.0.17.55(16.20.0)	
1034754	Content-Length: 0

Heres another call attempt:

<--- Transmitting SIP response (613 bytes) to TCP:159.65.252.186:33919 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/TCP 10.65.6.1:33919;rport=33919;received=159.65.252.186;branch=z9hG4bK8tZgJYYy8gvPzDIm
Call-ID: C52B73A551CB52BFE0AB8F2F5DB5ED84B8D2628D
From: <sip:[email protected]>;tag=AE6A0853D99D0CD4E2C2CDCC11477EA0
To: <sip:[email protected]>;tag=z9hG4bK8tZgJYYy8gvPzDIm
CSeq: 23278 REGISTER
WWW-Authenticate: Digest realm="asterisk",nonce="1651772649/fcde43714fc8f52c054ded5bd28481c7",opaque="68c25efc4536cd2c",algorithm=md5,qop="auth"
Server: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


<--- Transmitting SIP request (708 bytes) to TCP:159.65.252.186:33919 --->
NOTIFY sip:[email protected]:33919;transport=TCP;rinstance=7EA086A9 SIP/2.0
Via: SIP/2.0/TCP 212.95.115.1:5060;rport;branch=z9hG4bKPjbaed8191-2d73-4c93-8543-9560594001b3;alias
From: <sip:[email protected]>;tag=5efdc17c-8302-4bfd-be72-a5783a88d93a
To: <sip:[email protected];rinstance=7EA086A9>
Contact: <sip:[email protected]:5060;transport=TCP>
Call-ID: 66a5b779-7c77-4393-b9ce-423a5d94a6f1
CSeq: 29951 NOTIFY
Subscription-State: terminated
Event: message-summary
Allow-Events: presence, dialog, message-summary, refer
Max-Forwards: 70
User-Agent: FPBX-15.0.17.55(16.20.0)
Content-Type: application/simple-message-summary
Content-Length:    48

Messages-Waiting: no
Voice-Message: 0/0 (0/0)

<--- Received SIP response (482 bytes) from UDP:10.200.20.65:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj8492d47a-c49e-4e21-b2bb-7eeead178af2
From: <sip:[email protected]>;tag=cfc2062e-6b0e-4f52-b63f-7679d9f79443
To: <sip:[email protected]>;tag=251930052
Call-ID: abadcb83-13a5-4f3c-be8f-bf94abe1adb7
CSeq: 4411 NOTIFY
Supported: replaces, path, timer
User-Agent: Grandstream GXP2170 1.0.11.10
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0


<--- Received SIP request (1210 bytes) from UDP:10.200.20.89:5060 --->
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 10.200.20.89:5060;branch=z9hG4bK1990948889;rport
Route: <sip:10.200.20.5:5060;lr>
From: "P.Geschke" <sip:[email protected]>;tag=1669003750
To: <sip:[email protected]>
Call-ID: [email protected]
CSeq: 240 INVITE
Contact: "P.Geschke" <sip:[email protected]:5060>
X-Grandstream-PBX: true
Max-Forwards: 70
User-Agent: Grandstream GXP2170 1.0.11.10
Privacy: none
P-Preferred-Identity: "P.Geschke" <sip:[email protected]>
P-Emergency-Info: IEEE-EUI-48;eui-48-addr=C0-74-AD-38-AA-02
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length:   432

v=0
o=995 8000 8000 IN IP4 10.200.20.89
s=SIP Call
c=IN IP4 10.200.20.89
t=0 0
m=audio 5050 RTP/AVP 0 8 4 18 9 97 2 123 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:8 PCMA/8000
a=rtpmap:4 G723/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:2 G726-32/8000
a=rtpmap:123 opus/48000/2
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

<--- Transmitting SIP response (486 bytes) to UDP:10.200.20.89:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.200.20.89:5060;rport=5060;received=10.200.20.89;branch=z9hG4bK1990948889
Call-ID: [email protected]
From: "P.Geschke" <sip:[email protected]>;tag=1669003750
To: <sip:[email protected]>;tag=z9hG4bK1990948889
CSeq: 240 INVITE
WWW-Authenticate: Digest realm="asterisk",nonce="1651772649/04ddfc1b2a6fa37b91c161df0d20898a",opaque="6b9dc33551a30d99",algorithm=md5,qop="auth"
Server: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


<--- Received SIP request (316 bytes) from UDP:10.200.20.89:5060 --->
ACK sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 10.200.20.89:5060;branch=z9hG4bK1990948889;rport
Route: <sip:10.200.20.5:5060;lr>
From: "P.Geschke" <sip:[email protected]>;tag=1669003750
To: <sip:[email protected]>;tag=z9hG4bK1990948889
Call-ID: [email protected]
CSeq: 240 ACK
Content-Length: 0


<--- Received SIP request (1475 bytes) from UDP:10.200.20.89:5060 --->
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 10.200.20.89:5060;branch=z9hG4bK1852595862;rport
Route: <sip:10.200.20.5:5060;lr>
From: "P.Geschke" <sip:[email protected]>;tag=1669003750
To: <sip:[email protected]>
Call-ID: [email protected]
CSeq: 241 INVITE
Contact: "P.Geschke" <sip:[email protected]:5060>
Authorization: Digest username="995", realm="asterisk", nonce="1651772649/04ddfc1b2a6fa37b91c161df0d20898a", uri="sip:[email protected]", response="eac69c1ee5fe9f3dc4c4d0b5159b78f8", algorithm=md5, cnonce="03022719", opaque="6b9dc33551a30d99", qop=auth, nc=00000001
X-Grandstream-PBX: true
Max-Forwards: 70
User-Agent: Grandstream GXP2170 1.0.11.10
Privacy: none
P-Preferred-Identity: "P.Geschke" <sip:[email protected]>
P-Emergency-Info: IEEE-EUI-48;eui-48-addr=C0-74-AD-38-AA-02
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length:   432

v=0
o=995 8000 8000 IN IP4 10.200.20.89
s=SIP Call
c=IN IP4 10.200.20.89
t=0 0
m=audio 5050 RTP/AVP 0 8 4 18 9 97 2 123 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:8 PCMA/8000
a=rtpmap:4 G723/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:2 G726-32/8000
a=rtpmap:123 opus/48000/2
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

<--- Transmitting SIP response (312 bytes) to UDP:10.200.20.89:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.200.20.89:5060;rport=5060;received=10.200.20.89;branch=z9hG4bK1852595862
Call-ID: [email protected]
From: "P.Geschke" <sip:[email protected]>;tag=1669003750
To: <sip:[email protected]>
CSeq: 241 INVITE
Server: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


[2022-05-05 19:44:09] ERROR[8963][C-00002a79]: pbx_functions.c:608 ast_func_read: Function SIP_HEADER not registered
[2022-05-05 19:44:09] ERROR[8963][C-00002a79]: pbx_functions.c:651 ast_func_read2: Function SIP_HEADER not registered
[2022-05-05 19:44:09] ERROR[8963][C-00002a79]: pbx_functions.c:608 ast_func_read: Function SIP_HEADER not registered
[2022-05-05 19:44:09] ERROR[8963][C-00002a79]: pbx_functions.c:651 ast_func_read2: Function SIP_HEADER not registered
<--- Transmitting SIP response (390 bytes) to UDP:10.200.20.89:5060 --->
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/UDP 10.200.20.89:5060;rport=5060;received=10.200.20.89;branch=z9hG4bK1852595862
Call-ID: [email protected]
From: "P.Geschke" <sip:[email protected]>;tag=1669003750
To: <sip:[email protected]>;tag=0f832b89-7ef3-4c5e-b01e-fbc679d6bcba
CSeq: 241 INVITE
Server: FPBX-15.0.17.55(16.20.0)
Reason: Q.850;cause=34
Content-Length:  0


<--- Received SIP request (335 bytes) from UDP:10.200.20.89:5060 --->
ACK sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 10.200.20.89:5060;branch=z9hG4bK1852595862;rport
Route: <sip:10.200.20.5:5060;lr>
From: "P.Geschke" <sip:[email protected]>;tag=1669003750
To: <sip:[email protected]>;tag=0f832b89-7ef3-4c5e-b01e-fbc679d6bcba
Call-ID: [email protected]
CSeq: 241 ACK
Content-Length: 0


<--- Transmitting SIP response (612 bytes) to TCP:159.65.252.186:26007 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/TCP 10.65.6.4:26007;rport=26007;received=159.65.252.186;branch=z9hG4bKvrokz9UDYHlsph5u
Call-ID: 72B6F304A07C19E2404FCDD8DEB9E6C9B136C55F
From: <sip:[email protected]>;tag=236C256AEC287948058CFAAF5972A9BC
To: <sip:[email protected]>;tag=z9hG4bKvrokz9UDYHlsph5u
CSeq: 2451 REGISTER
WWW-Authenticate: Digest realm="asterisk",nonce="1651772650/dcfacc83d3888ab2658f600f675b44be",opaque="6c122d7a3703649b",algorithm=md5,qop="auth"
Server: FPBX-15.0.17.55(16.20.0)
Content-Length:  0

david55 · May 5, 2022, 5:50pm

Because it is good practice to include it, as I can’t think of a case where it causes problems, and it can help a lot in NATted environments. I think you will find that the default FreePBX configuration includes force_rport, which causes a protocol violation, resulting in rport being assumed even when not set (or is that just symmetric_rtp?). People put it there because, in spite of causing a protocol violation, it tend to make things work in the real world. However, in this case, rport is being used in a completely compliant way.

Actually one of my pet peeves is the number of options people put into sip.conf settings that are only really there because they cut and pasted from examples where they were put in because people thought there was a need when there wasn’t. This is exacerbated on chan_sip, because the parameter is called nat, and people think it has to be on in typical NAT configurations, which isn’t necessarily true.

There are worse ones: people blindly put insecure=port,invite (or even the giveaway name, “very”, when port is rarely needed, and there are common cases where invite is not needed.

david55 · May 5, 2022, 5:56pm

There isn’t enough logging to be sure why it is rejected, but I’d assume it was because the destination wasn’t registered.

This is asking for the register to be authenticated. Your log stops before that happens, so either the requestor doesn’t know what credentials to use, or you cut off the log before the useful bit.

pge · May 5, 2022, 5:57pm

I’ll gladly post the entire thing again.
Give me a sec.

pge · May 5, 2022, 5:59pm

<--- Received SIP request (1208 bytes) from UDP:10.200.20.89:5060 --->
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 10.200.20.89:5060;branch=z9hG4bK293026923;rport
Route: <sip:10.200.20.5:5060;lr>
From: "P.Geschke" <sip:[email protected]>;tag=112990512
To: <sip:[email protected]>
Call-ID: [email protected]
CSeq: 280 INVITE
Contact: "P.Geschke" <sip:[email protected]:5060>
X-Grandstream-PBX: true
Max-Forwards: 70
User-Agent: Grandstream GXP2170 1.0.11.10
Privacy: none
P-Preferred-Identity: "P.Geschke" <sip:[email protected]>
P-Emergency-Info: IEEE-EUI-48;eui-48-addr=C0-74-AD-38-AA-02
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length:   432

v=0
o=995 8000 8000 IN IP4 10.200.20.89
s=SIP Call
c=IN IP4 10.200.20.89
t=0 0
m=audio 5058 RTP/AVP 0 8 4 18 9 97 2 123 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:8 PCMA/8000
a=rtpmap:4 G723/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:2 G726-32/8000
a=rtpmap:123 opus/48000/2
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

<--- Transmitting SIP response (483 bytes) to UDP:10.200.20.89:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.200.20.89:5060;rport=5060;received=10.200.20.89;branch=z9hG4bK293026923
Call-ID: [email protected]
From: "P.Geschke" <sip:[email protected]>;tag=112990512
To: <sip:[email protected]>;tag=z9hG4bK293026923
CSeq: 280 INVITE
WWW-Authenticate: Digest realm="asterisk",nonce="1651773545/04c78d2cd72ce4d9f1fe3b443aeeab04",opaque="73b32dcf48998d88",algorithm=md5,qop="auth"
Server: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


<--- Received SIP request (313 bytes) from UDP:10.200.20.89:5060 --->
ACK sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 10.200.20.89:5060;branch=z9hG4bK293026923;rport
Route: <sip:10.200.20.5:5060;lr>
From: "P.Geschke" <sip:[email protected]>;tag=112990512
To: <sip:[email protected]>;tag=z9hG4bK293026923
Call-ID: [email protected]
CSeq: 280 ACK
Content-Length: 0


<--- Received SIP request (1474 bytes) from UDP:10.200.20.89:5060 --->
INVITE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 10.200.20.89:5060;branch=z9hG4bK1676200976;rport
Route: <sip:10.200.20.5:5060;lr>
From: "P.Geschke" <sip:[email protected]>;tag=112990512
To: <sip:[email protected]>
Call-ID: [email protected]
CSeq: 281 INVITE
Contact: "P.Geschke" <sip:[email protected]:5060>
Authorization: Digest username="995", realm="asterisk", nonce="1651773545/04c78d2cd72ce4d9f1fe3b443aeeab04", uri="sip:[email protected]", response="688c3d2da318e7178d95e904a59c16bd", algorithm=md5, cnonce="05082408", opaque="73b32dcf48998d88", qop=auth, nc=00000001
X-Grandstream-PBX: true
Max-Forwards: 70
User-Agent: Grandstream GXP2170 1.0.11.10
Privacy: none
P-Preferred-Identity: "P.Geschke" <sip:[email protected]>
P-Emergency-Info: IEEE-EUI-48;eui-48-addr=C0-74-AD-38-AA-02
Supported: replaces, path, timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Accept: application/sdp, application/dtmf-relay
Content-Length:   432

v=0
o=995 8000 8000 IN IP4 10.200.20.89
s=SIP Call
c=IN IP4 10.200.20.89
t=0 0
m=audio 5058 RTP/AVP 0 8 4 18 9 97 2 123 101
a=sendrecv
a=rtpmap:0 PCMU/8000
a=ptime:20
a=rtpmap:8 PCMA/8000
a=rtpmap:4 G723/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:2 G726-32/8000
a=rtpmap:123 opus/48000/2
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

<--- Transmitting SIP response (311 bytes) to UDP:10.200.20.89:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.200.20.89:5060;rport=5060;received=10.200.20.89;branch=z9hG4bK1676200976
Call-ID: [email protected]
From: "P.Geschke" <sip:[email protected]>;tag=112990512
To: <sip:[email protected]>
CSeq: 281 INVITE
Server: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


[2022-05-05 19:59:05] ERROR[11130][C-00002a7d]: pbx_functions.c:608 ast_func_read: Function SIP_HEADER not registered
[2022-05-05 19:59:05] ERROR[11130][C-00002a7d]: pbx_functions.c:651 ast_func_read2: Function SIP_HEADER not registered
[2022-05-05 19:59:05] ERROR[11130][C-00002a7d]: pbx_functions.c:608 ast_func_read: Function SIP_HEADER not registered
[2022-05-05 19:59:05] ERROR[11130][C-00002a7d]: pbx_functions.c:651 ast_func_read2: Function SIP_HEADER not registered
<--- Transmitting SIP response (389 bytes) to UDP:10.200.20.89:5060 --->
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/UDP 10.200.20.89:5060;rport=5060;received=10.200.20.89;branch=z9hG4bK1676200976
Call-ID: [email protected]
From: "P.Geschke" <sip:[email protected]>;tag=112990512
To: <sip:[email protected]>;tag=b39acc09-8bb4-417e-82e2-5178234c083b
CSeq: 281 INVITE
Server: FPBX-15.0.17.55(16.20.0)
Reason: Q.850;cause=34
Content-Length:  0


<--- Received SIP request (334 bytes) from UDP:10.200.20.89:5060 --->
ACK sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 10.200.20.89:5060;branch=z9hG4bK1676200976;rport
Route: <sip:10.200.20.5:5060;lr>
From: "P.Geschke" <sip:[email protected]>;tag=112990512
To: <sip:[email protected]>;tag=b39acc09-8bb4-417e-82e2-5178234c083b
Call-ID: [email protected]
CSeq: 281 ACK
Content-Length: 0


<--- Transmitting SIP request (418 bytes) to UDP:10.200.20.66:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 10.200.20.5:5060;rport;branch=z9hG4bKPj4120f141-c2cd-4b45-99f5-60c6ecdd5669
From: <sip:[email protected]>;tag=1636f878-4be6-43a0-99f0-5a7462472b82
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 99e24ab4-1550-451d-9a27-45041629793e
CSeq: 13721 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


<--- Received SIP response (485 bytes) from UDP:10.200.20.66:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj4120f141-c2cd-4b45-99f5-60c6ecdd5669
From: <sip:[email protected]>;tag=1636f878-4be6-43a0-99f0-5a7462472b82
To: <sip:[email protected]>;tag=1562420990
Call-ID: 99e24ab4-1550-451d-9a27-45041629793e
CSeq: 13721 OPTIONS
Supported: replaces, path, timer
User-Agent: Grandstream GXP2170 1.0.11.10
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0


<--- Transmitting SIP request (470 bytes) to UDP:195.185.37.60:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 212.95.115.1:5060;rport;branch=z9hG4bKPj875d8754-3b5e-478f-a9e0-ef542805aa95
From: <sip:[email protected]>;tag=7316d1b3-c8ed-4e27-9fe5-2c615211c4c5
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 66f95ff0-f6a3-4c90-bb81-685a4f8a9a70
CSeq: 63268 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


<--- Received SIP response (392 bytes) from UDP:195.185.37.60:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 212.95.115.1:5060;rport=42952;branch=z9hG4bKPj875d8754-3b5e-478f-a9e0-ef542805aa95;received=212.95.115.1
From: <sip:[email protected]>;tag=7316d1b3-c8ed-4e27-9fe5-2c615211c4c5
To: <sip:[email protected]>;tag=69553D11-6274106D00011B07-6BCFC700
Call-ID: 66f95ff0-f6a3-4c90-bb81-685a4f8a9a70
CSeq: 63268 OPTIONS
Content-Length: 0


<--- Transmitting SIP request (418 bytes) to UDP:10.200.20.74:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 10.200.20.5:5060;rport;branch=z9hG4bKPj41e09f9d-3755-4bee-abbd-7beaa87e6e19
From: <sip:[email protected]>;tag=5a18359a-f128-4e4b-bf7e-97780e678053
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 7abffb15-88e0-4ada-a107-14a1eae5494a
CSeq: 45270 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


<--- Transmitting SIP request (442 bytes) to UDP:10.200.20.200:5060 --->
OPTIONS sip:[email protected]:5060;line=53262 SIP/2.0
Via: SIP/2.0/UDP 10.200.20.5:5060;rport;branch=z9hG4bKPj2d83a763-fdeb-49ca-97b0-f8e021f4f080
From: <sip:[email protected]>;tag=972ef558-3de4-418b-9383-e067e98787f1
To: <sip:[email protected];line=53262>
Contact: <sip:[email protected]:5060>
Call-ID: 108d4f74-26bb-4d23-b074-392dc38541ac
CSeq: 61824 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


<--- Received SIP response (485 bytes) from UDP:10.200.20.74:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj41e09f9d-3755-4bee-abbd-7beaa87e6e19
From: <sip:[email protected]>;tag=5a18359a-f128-4e4b-bf7e-97780e678053
To: <sip:[email protected]>;tag=1575473613
Call-ID: 7abffb15-88e0-4ada-a107-14a1eae5494a
CSeq: 45270 OPTIONS
Supported: replaces, path, timer
User-Agent: Grandstream GXP2170 1.0.11.16
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0


<--- Received SIP response (609 bytes) from UDP:10.200.20.200:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj2d83a763-fdeb-49ca-97b0-f8e021f4f080
Max-Forwards: 70
From: <sip:[email protected]>;tag=972ef558-3de4-418b-9383-e067e98787f1
To: <sip:[email protected];line=53262>
Call-ID: 108d4f74-26bb-4d23-b074-392dc38541ac
CSeq: 61824 OPTIONS
Accept: application/sdp
Accept-Encoding: identity
Accept-Language: 
Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK, UPDATE
Supported: replaces,100rel
User-Agent: snomM900/05.00.0001 (MAC=000413B6588E; SER= 00000; HW=2)
Content-Length: 0


<--- Transmitting SIP request (497 bytes) to TCP:159.65.252.186:26007 --->
OPTIONS sip:[email protected]:26007;transport=TCP;rinstance=BEC3D8FB SIP/2.0
Via: SIP/2.0/TCP 212.95.115.1:5060;rport;branch=z9hG4bKPjb9749e22-001e-4cd8-940d-a63b5835130e;alias
From: <sip:[email protected]>;tag=a1864b42-8596-4396-bda9-7c1187a9dbfe
To: <sip:[email protected];rinstance=BEC3D8FB>
Contact: <sip:[email protected]:5060;transport=TCP>
Call-ID: 35e47184-cccf-446b-a9e9-77940efd0f6a
CSeq: 33877 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


<--- Received SIP response (545 bytes) from TCP:159.65.252.186:26007 --->
SIP/2.0 200 OK
Via: SIP/2.0/TCP 212.95.115.1:5060;rport=5060;branch=z9hG4bKPjb9749e22-001e-4cd8-940d-a63b5835130e;alias;received=212.95.115.1
Contact: <sip:[email protected]:26007;transport=tcp>
From: <sip:[email protected]>;tag=a1864b42-8596-4396-bda9-7c1187a9dbfe
Call-ID: 35e47184-cccf-446b-a9e9-77940efd0f6a
CSeq: 33877 OPTIONS
To: <sip:[email protected];rinstance=BEC3D8FB>
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces, path
Accept: application/sdp
User-Agent: Acrobits SIPIS
Content-Length: 0


<--- Transmitting SIP request (418 bytes) to UDP:10.200.20.69:5060 --->
OPTIONS sip:[email protected]:5060 SIP/2.0
Via: SIP/2.0/UDP 10.200.20.5:5060;rport;branch=z9hG4bKPj9341716c-cbbe-499e-8b54-c0c77676fcf0
From: <sip:[email protected]>;tag=b6c3a4cf-bf1a-4839-8835-8deb208bbf30
To: <sip:[email protected]>
Contact: <sip:[email protected]:5060>
Call-ID: 087419de-17c8-415f-8be6-63b5afb96dc5
CSeq: 21630 OPTIONS
Max-Forwards: 70
User-Agent: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


<--- Received SIP response (485 bytes) from UDP:10.200.20.69:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.200.20.5:5060;rport=5060;branch=z9hG4bKPj9341716c-cbbe-499e-8b54-c0c77676fcf0
From: <sip:[email protected]>;tag=b6c3a4cf-bf1a-4839-8835-8deb208bbf30
To: <sip:[email protected]>;tag=1257978136
Call-ID: 087419de-17c8-415f-8be6-63b5afb96dc5
CSeq: 21630 OPTIONS
Supported: replaces, path, timer
User-Agent: Grandstream GXP2170 1.0.11.16
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0

david55 · May 5, 2022, 6:01pm

I meant that you didn’t have a high enough logging verbosity to see the dialplan execution and messages saying why there were “No circuit/channel available” (cause code 34).

pge · May 5, 2022, 6:03pm

Oh, alright. Heres the registration:

<--- Received SIP request (754 bytes) from TCP:10.200.20.90:2111 --->
REGISTER sip:10.200.20.5 SIP/2.0
Authorization: Digest username="401",realm="asterisk",nonce="1651773514/b05318bba3f3999501a6e7192c95931e",response="661a8acd7c7aceeab2699ce20007597a",uri="sip:10.200.20.5",qop=auth,cnonce="0b749bee810870cc",nc=00000002,opaque="08fa169c76b4c322",algorithm=MD5
Via: SIP/2.0/TCP 10.200.20.90:5060;branch=z9hG4bK-C00BBD6D;rport
From: <sip:[email protected]>;tag=488043571
To: <sip:[email protected]>
Call-ID: 9e3b7ffd0274620141ab0090334f60a2
CSeq: 1048 REGISTER
Contact: <sip:[email protected]:5060;transport=TCP>;expires=300
Accept: innovaphone/data
Content-Length: 0
Expires: 300
Max-Forwards: 70
User-Agent: (innovaphone IP111A/13r1 sr26 [13.2940/132523/1300])
Allow-Events: reg,dialog,message-summary,presence


<--- Transmitting SIP response (487 bytes) to TCP:10.200.20.90:2111 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/TCP 10.200.20.90:5060;rport=2111;received=10.200.20.90;branch=z9hG4bK-C00BBD6D
Call-ID: 9e3b7ffd0274620141ab0090334f60a2
From: <sip:[email protected]>;tag=488043571
To: <sip:[email protected]>;tag=z9hG4bK-C00BBD6D
CSeq: 1048 REGISTER
WWW-Authenticate: Digest realm="asterisk",nonce="1651773662/b0f963dc5e32fe306dca92b23149c159",opaque="2c768b7f2641891b",stale=true,algorithm=md5,qop="auth"
Server: FPBX-15.0.17.55(16.20.0)
Content-Length:  0


<--- Received SIP request (754 bytes) from TCP:10.200.20.90:2111 --->
REGISTER sip:10.200.20.5 SIP/2.0
Authorization: Digest username="401",realm="asterisk",nonce="1651773662/b0f963dc5e32fe306dca92b23149c159",response="81aa313e38e84139d7b22ceb5ff84b18",uri="sip:10.200.20.5",qop=auth,cnonce="0b749bee810870cc",nc=00000001,opaque="2c768b7f2641891b",algorithm=MD5
Via: SIP/2.0/TCP 10.200.20.90:5060;branch=z9hG4bK-C00BBD6E;rport
From: <sip:[email protected]>;tag=488043571
To: <sip:[email protected]>
Call-ID: 9e3b7ffd0274620141ab0090334f60a2
CSeq: 1049 REGISTER
Contact: <sip:[email protected]:5060;transport=TCP>;expires=300
Accept: innovaphone/data
Content-Length: 0
Expires: 300
Max-Forwards: 70
User-Agent: (innovaphone IP111A/13r1 sr26 [13.2940/132523/1300])
Allow-Events: reg,dialog,message-summary,presence


<--- Transmitting SIP response (435 bytes) to TCP:10.200.20.90:2111 --->
SIP/2.0 200 OK
Via: SIP/2.0/TCP 10.200.20.90:5060;rport=2111;received=10.200.20.90;branch=z9hG4bK-C00BBD6E
Call-ID: 9e3b7ffd0274620141ab0090334f60a2
From: <sip:[email protected]>;tag=488043571
To: <sip:[email protected]>;tag=z9hG4bK-C00BBD6E
CSeq: 1049 REGISTER
Date: Thu, 05 May 2022 18:01:02 GMT
Contact: <sip:[email protected]:2111;transport=TCP>;expires=299
Expires: 300
Server: FPBX-15.0.17.55(16.20.0)
Content-Length:  0

What verbosity level would i require?

david55 · May 5, 2022, 6:18pm

Does it leave the TCP connection up, after the register, or is it actually listening on port 2111, and can you TCP to that without being blocked?