Transferred call drops (fsfl101) - logs included (VERBOSE[3014])

Here is the log for a test call.

Called into the receptionist, transferred to Ext 101 ( fsfl101 ) , call immediately disconnects.
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++

2022-11-15 15:13:30] VERBOSE[3014][C-00019232] app_stack.c: SIP/fsfl101-000319a0 Internal Gosub(before-connecting-call,s,1(8c722eb3d2a7c453,110,101,)) start
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:1] NoOp(“SIP/fsfl101-000319a0”, “Executing routines in the newly created channel before initiaing the call”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:2] Set(“SIP/fsfl101-000319a0”, “TENANT=8c722eb3d2a7c453”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:3] Set(“SIP/fsfl101-000319a0”, “CALLER=110”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:4] Set(“SIP/fsfl101-000319a0”, “CALLEE=101”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:5] Set(“SIP/fsfl101-000319a0”, “EXEC_AA=”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:6] Set(“SIP/fsfl101-000319a0”, “CUSTOM_ALERT_INFO=”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:7] Set(“SIP/fsfl101-000319a0”, “APP_TYPE=NONE”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:8] GosubIf(“SIP/fsfl101-000319a0”, “0?sub-auto-answer,s,1”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:9] GosubIf(“SIP/fsfl101-000319a0”, “0?sub-set-custom-header,s,1(Alert-Info,)”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:10] GosubIf(“SIP/fsfl101-000319a0”, “0?sub-set-custom-header,s,1(Call-Info,)”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:11] Gosub(“SIP/fsfl101-000319a0”, “sub-set-custom-header,s,1(CALL-TYPE,LOCAL)”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@sub-set-custom-header:1] NoOp(“SIP/fsfl101-000319a0”, “Setting up custom header”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@sub-set-custom-header:2] GotoIf(“SIP/fsfl101-000319a0”, “1?set-sip”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@sub-set-custom-header:6] NoOp(“SIP/fsfl101-000319a0”, “Add SIP Headers”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@sub-set-custom-header:7] SIPAddHeader(“SIP/fsfl101-000319a0”, “CALL-TYPE: LOCAL”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@sub-set-custom-header:8] Return(“SIP/fsfl101-000319a0”, “”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:12] Gosub(“SIP/fsfl101-000319a0”, “sub-set-custom-header,s,1(APPLICATION,NONE)”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@sub-set-custom-header:1] NoOp(“SIP/fsfl101-000319a0”, “Setting up custom header”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@sub-set-custom-header:2] GotoIf(“SIP/fsfl101-000319a0”, “1?set-sip”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@sub-set-custom-header:6] NoOp(“SIP/fsfl101-000319a0”, “Add SIP Headers”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@sub-set-custom-header:7] SIPAddHeader(“SIP/fsfl101-000319a0”, “APPLICATION: NONE”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@sub-set-custom-header:8] Return(“SIP/fsfl101-000319a0”, “”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:13] GosubIf(“SIP/fsfl101-000319a0”, “0?sub-set-custom-header,s,1(QUEUE-NAME,)”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:14] GosubIf(“SIP/fsfl101-000319a0”, “0?T7_before-connecting-call-hook,s,1”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] pbx.c: Executing [s@before-connecting-call:15] Return(“SIP/fsfl101-000319a0”, “”) in new stack
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] app_stack.c: Spawn extension (T7_cos-all, 101, 1) exited non-zero on ‘SIP/fsfl101-000319a0’
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] app_stack.c: SIP/fsfl101-000319a0 Internal Gosub(before-connecting-call,s,1(8c722eb3d2a7c453,110,101,)) complete GOSUB_RETVAL=
[2022-11-15 15:13:30] VERBOSE[3014][C-00019232] app_dial.c: Called SIP/fsfl101

Here are logs showing line calling IN…

2022-11-15 15:29:02] VERBOSE[11409][C-00019276] pbx.c: Executing [14078894128@T7_default-trunk:2] Gosub(“SIP/BVSIn4-00031a25”, “sub-check-blacklist,s,1(8c722eb3d2a7c453,4074019259)”) in new stack [2022-11-15 15:29:02] VERBOSE[11409][C-00019276] pbx.c: Executing [s@sub-check-blacklist:1] NoOp(“SIP/BVSIn4-00031a25”, “Testing if 4074019259 is in Black List”) in new stack [2022-11-15 15:29:02] VERBOSE[11409][C-00019276] pbx.c: Executing [14078894128@T7_default-trunk:3] Gosub(“SIP/BVSIn4-00031a25”, “sub-stir-shaken-verify,s,1(8c722eb3d2a7c453,4074019259)”) in new stack [2022-11-15 15:29:02] VERBOSE[11409][C-00019276] pbx.c: Executing [14078894128@T7_default-trunk:5] Gosub(“SIP/BVSIn4-00031a25”, “dynamic-routing-in,s,1(4074019259)”) in new stack [2022-11-15 15:29:02] VERBOSE[11409][C-00019276] pbx.c: Executing [s@dynamic-routing-in:2] Set(“SIP/BVSIn4-00031a25”, “EXTERNAL_CALLER=4074019259”) in new stack [2022-11-15 15:29:02] VERBOSE[11409][C-00019276] pbx.c: Executing [14078894128@T7_incoming-calls:5] Gosub(“SIP/BVSIn4-00031a25”, “sub-set-call-vars,s-incoming,1(4074019259,14078894128,8c722eb3d2a7c453)”) in new stack [2022-11-15 15:29:02] VERBOSE[11409][C-00019276] pbx.c: Executing [s-incoming@sub-set-call-vars:3] Set(“SIP/BVSIn4-00031a25”, “__INCOMING_SOURCE=4074019259”) in new stack [2022-11-15 15:29:02] VERBOSE[11409][C-00019276] pbx.c: Executing [s-incoming@sub-set-call-vars:6] Set(“SIP/BVSIn4-00031a25”, “__CALL_SOURCE=4074019259”) in new stack [2022-11-15 15:29:02] VERBOSE[11409][C-00019276] pbx.c: Executing [s-incoming@sub-set-call-vars:7] Set(“SIP/BVSIn4-00031a25”, “__CS=4074019259”) in new stack [2022-11-15 15:29:02] VERBOSE[11409][C-00019276] pbx.c: Executing [app-incoming@sub-set-call-vars:3] Set(“SIP/BVSIn4-00031a25”, “CDR(source)=4074019259”) in new stack [2022-11-15 15:29:08] VERBOSE[11409][C-00019276] pbx.c: Executing [4@IVR-25:2] System(“SIP/BVSIn4-00031a25”, “/usr/share/vitalpbx/scripts/ivr_stats “25” “4” “PROSOURCE TECH” “4074019259” “14078894128” “1668544142.568060"”) in new stack [2022-11-15 15:29:08] VERBOSE[11409][C-00019276] pbx.c: Executing [app-incoming@sub-set-call-vars:3] Set(“SIP/BVSIn4-00031a25”, “CDR(source)=4074019259”) in new stack [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] pbx.c: Executing [s@T7_cos-all:2] NoOp(“Local/110@T7_ring-group-dial-0001076b;2”, “Dialing 110 from 4074019259”) in new stack [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] pbx.c: Executing [s@sub-construct-cid:2] Set(“Local/110@T7_ring-group-dial-0001076b;2”, “CALL_SOURCE=4074019259") in new stack [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] pbx.c: Executing [s@sub-construct-cid:3] Set(“Local/110@T7_ring-group-dial-0001076b;2”, “CS=4074019259") in new stack [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] pbx.c: Executing [s-local@sub-get-device-tree:1] NoOp(“Local/110@T7_ring-group-dial-0001076b;2”, “Try to determianate caller technology 4074019259”) in new stack [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] pbx.c: Executing [s@sub-construct-cid:12] Set(“Local/110@T7_ring-group-dial-0001076b;2”, “CDR(source)=4074019259”) in new stack [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] pbx.c: Executing [110@sub-local-dialing:9] Set(“Local/110@T7_ring-group-dial-0001076b;2”, “DB(8c722eb3d2a7c453/LASTCALLER/110)=4074019259”) in new stack [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] pbx.c: Executing [110@sub-local-dialing:36] Set(“Local/110@T7_ring-group-dial-0001076b;2”, “DIAL_OPTIONS=ktrb(before-connecting-call^s^1(8c722eb3d2a7c453^4074019259^110^^))”) in new stack [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] pbx.c: Executing [110@sub-local-dialing:37] Set(“Local/110@T7_ring-group-dial-0001076b;2”, “DIAL_OPTIONS=ktrb(before-connecting-call^s^1(8c722eb3d2a7c453^4074019259^110^^))U(sub-call-recording^8c722eb3d2a7c453^4074019259^110^no)”) in new stack [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] pbx.c: Executing [110@sub-local-dialing:50] Dial(“Local/110@T7_ring-group-dial-0001076b;2”, “SIP/fsfl110,30,ktrb(before-connecting-call^s^1(8c722eb3d2a7c453^4074019259^110^^))U(sub-call-recording^8c722eb3d2a7c453^4074019259^110^no)”) in new stack [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] app_stack.c: SIP/fsfl110-00031a27 Internal Gosub(before-connecting-call,s,1(8c722eb3d2a7c453,4074019259,110,)) start [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] pbx.c: Executing [s@before-connecting-call:3] Set(“SIP/fsfl110-00031a27”, “CALLER=4074019259”) in new stack [2022-11-15 15:29:08] VERBOSE[11433][C-00019276] app_stack.c: SIP/fsfl110-00031a27 Internal Gosub(before-connecting-call,s,1(8c722eb3d2a7c453,4074019259,110,)) complete GOSUB_RETVAL= [2022-11-15 15:29:14] VERBOSE[11433][C-00019276] app_stack.c: SIP/fsfl110-00031a27 Internal Gosub(sub-call-recording,s,1(8c722eb3d2a7c453,4074019259,110,no)) start [2022-11-15 15:29:14] VERBOSE[11433][C-00019276] pbx.c: Executing [s@sub-call-recording:4] Set(“SIP/fsfl110-00031a27”, “CALLER=4074019259”) in new stack [2022-11-15 15:29:14] VERBOSE[11433][C-00019276] app_stack.c: SIP/fsfl110-00031a27 Internal Gosub(sub-call-recording,s,1(8c722eb3d2a7c453,4074019259,110,no)) complete GOSUB_RETVAL= [2022-11-15 15:29:42] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-check-diversions:2] Set(“Local/110@T7_ring-group-dial-0001076b;2”, "OLD_CALLER_ID="SAT:PROSOURCE TECH” <4074019259>") in new stack [2022-11-15 15:29:42] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-check-diversions:8] Set(“Local/110@T7_ring-group-dial-0001076b;2”, "CALLERID(all)="SAT:PROSOURCE TECH” <4074019259>”) in new stack

PL

Paul Lenic

11/15/2022 3:30 PM

[2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [101@sub-local-dialing:8] Set(“SIP/fsfl110-00031a2d”, “DIAL_STRING=SIP/fsfl101”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@parse-dial-string:1] NoOp(“SIP/fsfl110-00031a2d”, “Parsing dial string: SIP/fsfl101”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@parse-dial-string:4] Set(“SIP/fsfl110-00031a2d”, “CURRENT_DEVICE=SIP/fsfl101”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@parse-dial-string:7] Set(“SIP/fsfl110-00031a2d”, “USER=fsfl101”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@parse-dial-string:15] Set(“SIP/fsfl110-00031a2d”, “PARSED_DEV=SIP/fsfl101”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@parse-dial-string:17] Set(“SIP/fsfl110-00031a2d”, “NEW_DIAL_STRING=SIP/fsfl101”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@parse-dial-string:24] NoOp(“SIP/fsfl110-00031a2d”, “New dialstring: SIP/fsfl101”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@parse-dial-string:25] Set(“SIP/fsfl110-00031a2d”, “DIAL_STRING=SIP/fsfl101”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [101@sub-local-dialing:50] Dial(“SIP/fsfl110-00031a2d”, “SIP/fsfl101,30,ktrb(before-connecting-call^s^1(8c722eb3d2a7c453^110^101^^))U(sub-call-recording^8c722eb3d2a7c453^110^101^no)”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] app_stack.c: SIP/fsfl101-00031a2e Internal Gosub(before-connecting-call,s,1(8c722eb3d2a7c453,110,101,)) start [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:1] NoOp(“SIP/fsfl101-00031a2e”, “Executing routines in the newly created channel before initiaing the call”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:2] Set(“SIP/fsfl101-00031a2e”, “TENANT=8c722eb3d2a7c453”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:3] Set(“SIP/fsfl101-00031a2e”, “CALLER=110”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:4] Set(“SIP/fsfl101-00031a2e”, “CALLEE=101”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:5] Set(“SIP/fsfl101-00031a2e”, “EXEC_AA=”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:6] Set(“SIP/fsfl101-00031a2e”, “CUSTOM_ALERT_INFO=”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:7] Set(“SIP/fsfl101-00031a2e”, “APP_TYPE=NONE”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:8] GosubIf(“SIP/fsfl101-00031a2e”, “0?sub-auto-answer,s,1”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:9] GosubIf(“SIP/fsfl101-00031a2e”, “0?sub-set-custom-header,s,1(Alert-Info,)”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:10] GosubIf(“SIP/fsfl101-00031a2e”, “0?sub-set-custom-header,s,1(Call-Info,)”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:11] Gosub(“SIP/fsfl101-00031a2e”, “sub-set-custom-header,s,1(CALL-TYPE,LOCAL)”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-set-custom-header:1] NoOp(“SIP/fsfl101-00031a2e”, “Setting up custom header”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-set-custom-header:2] GotoIf(“SIP/fsfl101-00031a2e”, “1?set-sip”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-set-custom-header:6] NoOp(“SIP/fsfl101-00031a2e”, “Add SIP Headers”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-set-custom-header:7] SIPAddHeader(“SIP/fsfl101-00031a2e”, “CALL-TYPE: LOCAL”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-set-custom-header:8] Return(“SIP/fsfl101-00031a2e”, “”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:12] Gosub(“SIP/fsfl101-00031a2e”, “sub-set-custom-header,s,1(APPLICATION,NONE)”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-set-custom-header:1] NoOp(“SIP/fsfl101-00031a2e”, “Setting up custom header”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-set-custom-header:2] GotoIf(“SIP/fsfl101-00031a2e”, “1?set-sip”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-set-custom-header:6] NoOp(“SIP/fsfl101-00031a2e”, “Add SIP Headers”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-set-custom-header:7] SIPAddHeader(“SIP/fsfl101-00031a2e”, “APPLICATION: NONE”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@sub-set-custom-header:8] Return(“SIP/fsfl101-00031a2e”, “”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:13] GosubIf(“SIP/fsfl101-00031a2e”, “0?sub-set-custom-header,s,1(QUEUE-NAME,)”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:14] GosubIf(“SIP/fsfl101-00031a2e”, “0?T7_before-connecting-call-hook,s,1”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] pbx.c: Executing [s@before-connecting-call:15] Return(“SIP/fsfl101-00031a2e”, “”) in new stack [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] app_stack.c: Spawn extension (T7_cos-all, 101, 1) exited non-zero on ‘SIP/fsfl101-00031a2e’ [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] app_stack.c: SIP/fsfl101-00031a2e Internal Gosub(before-connecting-call,s,1(8c722eb3d2a7c453,110,101,)) complete GOSUB_RETVAL= [2022-11-15 15:29:36] VERBOSE[11608][C-0001927b] app_dial.c: Called SIP/fsfl101

Please use pastebin.com to share logs.

Dumping long lines that is super not easy to read is very discouraging

Will do PitzKey, thanks

This issue has been solved.

Turns out that the UDP Timeout for Firewall rules was set at 30, increased the timeout to 600, seems to have solved the issue (Sonicwall)