SIP Provider Repeatedly Reachable/Unreachable Causing No Outgoing Audio

Main issue: outgoing audio randomly drops for ~30 seconds, we can still hear the other end, if the other end waits long enough the audio returns. Of course, usually people just hang up because they think the call is dead.

Here are the logs from the middle of the night:

[2019-06-12 04:30:02] VERBOSE[40216] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US2_Oregon is now Reachable
[2019-06-12 04:30:02] VERBOSE[40216] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US2_Oregon/sip:[email protected]:5060 is now Reachable. RTT: 84.045 msec
[2019-06-12 04:30:26] VERBOSE[4574] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US1_Virginia is now Reachable
[2019-06-12 04:30:26] VERBOSE[4574] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US1_Virginia/sip:[email protected]:5060 is now Reachable. RTT: 1986.810 msec
[2019-06-12 04:38:54] VERBOSE[36065] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US2_Oregon is now Unreachable
[2019-06-12 04:38:54] VERBOSE[36065] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US2_Oregon/sip:[email protected]:5060 is now Unreachable. RTT: 0.000 msec
[2019-06-12 04:38:57] VERBOSE[11566] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US1_Virginia is now Unreachable
[2019-06-12 04:38:57] VERBOSE[11566] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US1_Virginia/sip:[email protected]:5060 is now Unreachable. RTT: 0.000 msec
[2019-06-12 04:39:09] VERBOSE[24759] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US1_Virginia is now Reachable
[2019-06-12 04:39:09] VERBOSE[24759] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US1_Virginia/sip:[email protected]:5060 is now Reachable. RTT: 51.799 msec
[2019-06-12 04:39:12] VERBOSE[11566] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US2_Oregon is now Reachable
[2019-06-12 04:39:12] VERBOSE[11566] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US2_Oregon/sip:[email protected]:5060 is now Reachable. RTT: 74.638 msec
[2019-06-12 04:44:22] VERBOSE[41975] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US1_Virginia is now Unreachable
[2019-06-12 04:44:22] VERBOSE[41975] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US1_Virginia/sip:[email protected]:5060 is now Unreachable. RTT: 0.000 msec
[2019-06-12 04:44:24] VERBOSE[24759] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US2_Oregon is now Unreachable
[2019-06-12 04:44:24] VERBOSE[24759] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US2_Oregon/sip:[email protected]:5060 is now Unreachable. RTT: 0.000 msec

This happens all night long.

And here is the last part of a call when the outgoing audio cuts out during the call:

[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk:15] Set("PJSIP/206-0000087e", "OUTNUM=+16822376643") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk:16] Set("PJSIP/206-0000087e", "custom=PJSIP") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf("PJSIP/206-0000087e", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk:18] ExecIf("PJSIP/206-0000087e", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk:19] Macro("PJSIP/206-0000087e", "dialout-trunk-predial-hook,") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("PJSIP/206-0000087e", "") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk:20] GotoIf("PJSIP/206-0000087e", "0?bypass,1") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk:21] ExecIf("PJSIP/206-0000087e", "1?Set(CONNECTEDLINE(num,i)=+16822376643)") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk:22] ExecIf("PJSIP/206-0000087e", "1?Set(CONNECTEDLINE(name,i)=CID:+14055737881)") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk:23] ExecIf("PJSIP/206-0000087e", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)+14055737881)") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk:24] GotoIf("PJSIP/206-0000087e", "0?customtrunk") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@macro-dialout-trunk:25] Dial("PJSIP/206-0000087e", "PJSIP/+16822376643@Twilio_PJSip_US2_Oregon,300,Tb(func-apply-sipheaders^s^1,(11))") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] app_stack.c: PJSIP/Twilio_PJSip_US2_Oregon-0000087f Internal Gosub(func-apply-sipheaders,s,1(11)) start
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("PJSIP/Twilio_PJSip_US2_Oregon-0000087f", "Applying SIP Headers to channel PJSIP/Twilio_PJSip_US2_Oregon-0000087f") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@func-apply-sipheaders:2] Set("PJSIP/Twilio_PJSip_US2_Oregon-0000087f", "TECH=PJSIP") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/Twilio_PJSip_US2_Oregon-0000087f", "SIPHEADERKEYS=") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@func-apply-sipheaders:4] While("PJSIP/Twilio_PJSip_US2_Oregon-0000087f", "0") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] app_while.c: Jumping to priority 11
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [s@func-apply-sipheaders:12] Return("PJSIP/Twilio_PJSip_US2_Oregon-0000087f", "") in new stack
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] app_stack.c: Spawn extension (from-pstn-e164-us, 16822376643, 1) exited non-zero on 'PJSIP/Twilio_PJSip_US2_Oregon-0000087f'
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] app_stack.c: PJSIP/Twilio_PJSip_US2_Oregon-0000087f Internal Gosub(func-apply-sipheaders,s,1(11)) complete GOSUB_RETVAL=
[2019-06-11 12:02:18] VERBOSE[41332][C-0000039d] app_dial.c: Called PJSIP/+16822376643@Twilio_PJSip_US2_Oregon
[2019-06-11 12:02:20] VERBOSE[41332][C-0000039d] app_dial.c: PJSIP/Twilio_PJSip_US2_Oregon-0000087f is making progress passing it to PJSIP/206-0000087e
[2019-06-11 12:02:20] VERBOSE[41332][C-0000039d] app_dial.c: PJSIP/Twilio_PJSip_US2_Oregon-0000087f is making progress passing it to PJSIP/206-0000087e
[2019-06-11 12:02:20] VERBOSE[41332][C-0000039d] app_dial.c: PJSIP/Twilio_PJSip_US2_Oregon-0000087f answered PJSIP/206-0000087e
[2019-06-11 12:02:20] VERBOSE[41339][C-0000039d] bridge_channel.c: Channel PJSIP/Twilio_PJSip_US2_Oregon-0000087f joined 'simple_bridge' basic-bridge <f7eb9821-0413-42c9-899f-e0c9696b9591>
[2019-06-11 12:02:20] VERBOSE[41332][C-0000039d] bridge_channel.c: Channel PJSIP/206-0000087e joined 'simple_bridge' basic-bridge <f7eb9821-0413-42c9-899f-e0c9696b9591>
[2019-06-11 12:03:52] VERBOSE[40216] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US2_Oregon is now Unreachable
[2019-06-11 12:03:52] VERBOSE[40216] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US2_Oregon/sip:[email protected]:5060 is now Unreachable. RTT: 0.000 msec
[2019-06-11 12:03:52] VERBOSE[24759] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US1_Virginia is now Unreachable
[2019-06-11 12:03:52] VERBOSE[24759] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US1_Virginia/sip:[email protected]:5060 is now Unreachable. RTT: 0.000 msec
[2019-06-11 12:04:18] VERBOSE[41339][C-0000039d] bridge_channel.c: Channel PJSIP/Twilio_PJSip_US2_Oregon-0000087f left 'simple_bridge' basic-bridge <f7eb9821-0413-42c9-899f-e0c9696b9591>
[2019-06-11 12:04:18] VERBOSE[41332][C-0000039d] bridge_channel.c: Channel PJSIP/206-0000087e left 'simple_bridge' basic-bridge <f7eb9821-0413-42c9-899f-e0c9696b9591>
[2019-06-11 12:04:18] VERBOSE[41332][C-0000039d] app_macro.c: Spawn extension (macro-dialout-trunk, s, 25) exited non-zero on 'PJSIP/206-0000087e' in macro 'dialout-trunk'
[2019-06-11 12:04:18] VERBOSE[41332][C-0000039d] pbx.c: Spawn extension (from-internal, 16822376643, 7) exited non-zero on 'PJSIP/206-0000087e'
[2019-06-11 12:04:18] VERBOSE[41332][C-0000039d] pbx.c: Executing [h@from-internal:1] Macro("PJSIP/206-0000087e", "hangupcall") in new stack

There you can see the endpoint becomes “Unreachable”, then the expected hangupcall 18 seconds later because they can’t hear us.

This doesn’t happen on every call, maybe half of them, and has been this way since we set the system up a few months ago.

Configuration Information:

  • SIP Provider: Twilio
  • pjsip (per the Twilio instruction guide)
  • PBX Firmware: 12.7.6-1904-1.sng7
  • Current PBX Version: 14.0.11
  • Asterisk 16.3.0 built by mockbuild @ jenkins7 on a x86_64 running Linux on 2019-04-17 16:33:59 UTC

I’m stumped on this one. Thanks for any insight you can provide.

Additional log: Sometimes we pick up the phone to make a call and it plays the “congestion” message. Here are those logs:

[2019-06-11 11:44:49] VERBOSE[32503] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US2_Oregon is now Reachable
[2019-06-11 11:44:49] VERBOSE[32503] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US2_Oregon/sip:[email protected]:5060 is now Reachable. RTT: 74.759 msec
[2019-06-11 11:44:49] VERBOSE[4574] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US1_Virginia is now Reachable
[2019-06-11 11:44:49] VERBOSE[4574] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US1_Virginia/sip:[email protected]:5060 is now Reachable. RTT: 42.962 msec
[2019-06-11 11:49:52] VERBOSE[11566] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US2_Oregon is now Unreachable
[2019-06-11 11:49:52] VERBOSE[11566] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US2_Oregon/sip:[email protected]:5060 is now Unreachable. RTT: 0.000 msec
[2019-06-11 11:49:52] VERBOSE[41975] res_pjsip/pjsip_configuration.c: Endpoint Twilio_PJSip_US1_Virginia is now Unreachable
[2019-06-11 11:49:52] VERBOSE[41975] res_pjsip/pjsip_options.c: Contact Twilio_PJSip_US1_Virginia/sip:[email protected]:5060 is now Unreachable. RTT: 0.000 msec
[2019-06-11 11:50:46] VERBOSE[41975] pbx_variables.c: Setting global variable 'SIPDOMAIN' to '192.168.100.2'
[2019-06-11 11:50:46] VERBOSE[41975] netsock2.c: Using SIP RTP Audio TOS bits 184
[2019-06-11 11:50:46] VERBOSE[41975] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.
[2019-06-11 11:50:46] VERBOSE[41975] netsock2.c: Using SIP RTP Audio CoS mark 5
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [16822376643@from-internal:1] Macro("PJSIP/206-00000878", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/206-00000878", "TOUCH_MONITOR=1560271846.2287") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/206-00000878", "AMPUSER=206") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("PJSIP/206-00000878", "0?report") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("PJSIP/206-00000878", "1?Set(REALCALLERIDNUM=206)") in new stack
...
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/206-00000878", "AMPUSERCIDNAME=Doug") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:8] ExecIf("PJSIP/206-00000878", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:9] GotoIf("PJSIP/206-00000878", "0?report") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/206-00000878", "AMPUSERCID=206") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:11] Set("PJSIP/206-00000878", "__DIAL_OPTIONS=HhTtr") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:12] Set("PJSIP/206-00000878", "CALLERID(all)="Doug" <206>") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:13] GotoIf("PJSIP/206-00000878", "0?limit") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:14] ExecIf("PJSIP/206-00000878", "1?Set(GROUP(concurrency_limit)=206)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("PJSIP/206-00000878", "1?Set(CHANNEL(language)=en)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:16] NoOp("PJSIP/206-00000878", "Macro Depth is 1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("PJSIP/206-00000878", "1?report2:macroerror") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-user-callerid,s,18)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("PJSIP/206-00000878", "1?continue") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:37] Set("PJSIP/206-00000878", "CALLERID(number)=206") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:38] Set("PJSIP/206-00000878", "CALLERID(name)=Doug") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:39] GotoIf("PJSIP/206-00000878", "0?cnum") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:40] Set("PJSIP/206-00000878", "CDR(cnam)=Doug") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:41] Set("PJSIP/206-00000878", "CDR(cnum)=206") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-user-callerid:42] Set("PJSIP/206-00000878", "CHANNEL(language)=en") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [16822376643@from-internal:2] Gosub("PJSIP/206-00000878", "sub-record-check,s,1(out,16822376643,dontcare)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/206-00000878", "0?initialized") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/206-00000878", "__REC_STATUS=INITIALIZED") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/206-00000878", "NOW=1560271846") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/206-00000878", "__DAY=11") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/206-00000878", "__MONTH=06") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/206-00000878", "__YEAR=2019") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/206-00000878", "__TIMESTR=20190611-115046") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/206-00000878", "__FROMEXTEN=206") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/206-00000878", "__MON_FMT=wav") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/206-00000878", "Recordings initialized") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/206-00000878", "0?Set(ARG3=dontcare)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/206-00000878", "REC_POLICY_MODE_SAVE=") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/206-00000878", "0?Set(REC_STATUS=NO)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/206-00000878", "3?checkaction") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/206-00000878", "1?sub-record-check,out,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (sub-record-check,out,1)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [out@sub-record-check:1] NoOp("PJSIP/206-00000878", "Outbound Recording Check from 206 to 16822376643") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [out@sub-record-check:2] Set("PJSIP/206-00000878", "RECMODE=dontcare") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [out@sub-record-check:3] ExecIf("PJSIP/206-00000878", "1?Goto(routewins)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (sub-record-check,out,7)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [out@sub-record-check:7] Gosub("PJSIP/206-00000878", "recordcheck,1(dontcare,out,16822376643)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/206-00000878", "Starting recording check against dontcare") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/206-00000878", "dontcare") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/206-00000878", "") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [out@sub-record-check:8] Return("PJSIP/206-00000878", "") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [16822376643@from-internal:3] ExecIf("PJSIP/206-00000878", "0 ?Set(CDR(accountcode)=)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [16822376643@from-internal:4] Set("PJSIP/206-00000878", "ROUTE_CIDSAVE="Doug" <206>") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [16822376643@from-internal:5] Set("PJSIP/206-00000878", "MOHCLASS=default") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [16822376643@from-internal:6] Set("PJSIP/206-00000878", "_NODEST=") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [16822376643@from-internal:7] Macro("PJSIP/206-00000878", "dialout-trunk,11,+16822376643,,off") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:1] Set("PJSIP/206-00000878", "DIAL_TRUNK=11") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:2] ExecIf("PJSIP/206-00000878", "0?Set(DIAL_OPTIONS=Hhtr)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:3] GosubIf("PJSIP/206-00000878", "0?sub-pincheck,s,1()") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:4] ExecIf("PJSIP/206-00000878", "0?Set(CALLERID(num)=206)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:5] GotoIf("PJSIP/206-00000878", "0?disabletrunk,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:6] Set("PJSIP/206-00000878", "DIAL_NUMBER=+16822376643") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:7] Set("PJSIP/206-00000878", "DIAL_TRUNK_OPTIONS=HhTtr") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:8] Set("PJSIP/206-00000878", "OUTBOUND_GROUP=OUT_11") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:9] Set("PJSIP/206-00000878", "DIAL_TRUNK_OPTIONS=T") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:10] GotoIf("PJSIP/206-00000878", "1?nomax") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-dialout-trunk,s,12)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:12] GotoIf("PJSIP/206-00000878", "0?skipoutcid") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:13] Macro("PJSIP/206-00000878", "outbound-callerid,11") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:1] NoOp("PJSIP/206-00000878", "206") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:2] NoOp("PJSIP/206-00000878", "") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:3] NoOp("PJSIP/206-00000878", "off") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf("PJSIP/206-00000878", "0?Set(CALLERPRES(name-pres)=)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:5] ExecIf("PJSIP/206-00000878", "0?Set(CALLERPRES(num-pres)=)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:6] ExecIf("PJSIP/206-00000878", "0?Set(REALCALLERIDNUM=206)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:7] ExecIf("PJSIP/206-00000878", "0?Set(AMPUSER=206)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:8] GotoIf("PJSIP/206-00000878", "1?normcid") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-outbound-callerid,s,12)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:12] Set("PJSIP/206-00000878", "USEROUTCID=") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:13] Set("PJSIP/206-00000878", "EMERGENCYCID=") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:14] Set("PJSIP/206-00000878", "TRUNKOUTCID=<+14055737881>") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:15] GotoIf("PJSIP/206-00000878", "1?trunkcid") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-outbound-callerid,s,21)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:21] ExecIf("PJSIP/206-00000878", "1?Set(CALLERID(all)=<+14055737881>)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf("PJSIP/206-00000878", "0?Set(CALLERID(all)=)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:23] ExecIf("PJSIP/206-00000878", "0?Set(CALLERID(all)=)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:24] ExecIf("PJSIP/206-00000878", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:25] ExecIf("PJSIP/206-00000878", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:26] Set("PJSIP/206-00000878", "CDR(outbound_cnum)=+14055737881") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:27] Set("PJSIP/206-00000878", "CDR(outbound_cnam)=") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:14] GosubIf("PJSIP/206-00000878", "0?sub-flp-11,s,1()") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:15] Set("PJSIP/206-00000878", "OUTNUM=+16822376643") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:16] Set("PJSIP/206-00000878", "custom=PJSIP") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf("PJSIP/206-00000878", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:18] ExecIf("PJSIP/206-00000878", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:19] Macro("PJSIP/206-00000878", "dialout-trunk-predial-hook,") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("PJSIP/206-00000878", "") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:20] GotoIf("PJSIP/206-00000878", "0?bypass,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:21] ExecIf("PJSIP/206-00000878", "1?Set(CONNECTEDLINE(num,i)=+16822376643)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:22] ExecIf("PJSIP/206-00000878", "1?Set(CONNECTEDLINE(name,i)=CID:+14055737881)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:23] ExecIf("PJSIP/206-00000878", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)+14055737881)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:24] GotoIf("PJSIP/206-00000878", "0?customtrunk") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:25] Dial("PJSIP/206-00000878", "PJSIP/+16822376643@Twilio_PJSip_US2_Oregon,300,Tb(func-apply-sipheaders^s^1,(11))") in new stack
[2019-06-11 11:50:46] ERROR[4574] res_pjsip.c: Endpoint 'Twilio_PJSip_US2_Oregon': Could not create dialog to invalid URI 'Twilio_PJSip_US2_Oregon'. Is endpoint registered and reachable?
[2019-06-11 11:50:46] ERROR[4574] chan_pjsip.c: Failed to create outgoing session to endpoint 'Twilio_PJSip_US2_Oregon'
[2019-06-11 11:50:46] WARNING[39303][C-00000399] app_dial.c: Unable to create channel of type 'PJSIP' (cause 3 - No route to destination)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:26] NoOp("PJSIP/206-00000878", "Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 3") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:27] GotoIf("PJSIP/206-00000878", "0?continue,1:s-CHANUNAVAIL,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set("PJSIP/206-00000878", "RC=3") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto("PJSIP/206-00000878", "3,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-dialout-trunk,3,1)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [3@macro-dialout-trunk:1] Goto("PJSIP/206-00000878", "continue,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-dialout-trunk,continue,1)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [continue@macro-dialout-trunk:1] NoOp("PJSIP/206-00000878", "TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 3 - failing through to other trunks") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [continue@macro-dialout-trunk:2] ExecIf("PJSIP/206-00000878", "1?Set(CALLERID(number)=206)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [16822376643@from-internal:8] Macro("PJSIP/206-00000878", "dialout-trunk,12,+16822376643,,off") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:1] Set("PJSIP/206-00000878", "DIAL_TRUNK=12") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:2] ExecIf("PJSIP/206-00000878", "0?Set(DIAL_OPTIONS=Hhtr)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:3] GosubIf("PJSIP/206-00000878", "0?sub-pincheck,s,1()") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:4] ExecIf("PJSIP/206-00000878", "0?Set(CALLERID(num)=206)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:5] GotoIf("PJSIP/206-00000878", "0?disabletrunk,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:6] Set("PJSIP/206-00000878", "DIAL_NUMBER=+16822376643") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:7] Set("PJSIP/206-00000878", "DIAL_TRUNK_OPTIONS=HhTtr") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:8] Set("PJSIP/206-00000878", "OUTBOUND_GROUP=OUT_12") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:9] Set("PJSIP/206-00000878", "DIAL_TRUNK_OPTIONS=T") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:10] GotoIf("PJSIP/206-00000878", "1?nomax") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-dialout-trunk,s,12)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:12] GotoIf("PJSIP/206-00000878", "0?skipoutcid") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:13] Macro("PJSIP/206-00000878", "outbound-callerid,12") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:1] NoOp("PJSIP/206-00000878", "206") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:2] NoOp("PJSIP/206-00000878", "") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:3] NoOp("PJSIP/206-00000878", "off") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf("PJSIP/206-00000878", "0?Set(CALLERPRES(name-pres)=)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:5] ExecIf("PJSIP/206-00000878", "0?Set(CALLERPRES(num-pres)=)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:6] ExecIf("PJSIP/206-00000878", "0?Set(REALCALLERIDNUM=206)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:7] ExecIf("PJSIP/206-00000878", "0?Set(AMPUSER=206)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:8] GotoIf("PJSIP/206-00000878", "1?normcid") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-outbound-callerid,s,12)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:12] Set("PJSIP/206-00000878", "USEROUTCID=") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:13] Set("PJSIP/206-00000878", "EMERGENCYCID=") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:14] Set("PJSIP/206-00000878", "TRUNKOUTCID=<+14055737881>") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:15] GotoIf("PJSIP/206-00000878", "1?trunkcid") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-outbound-callerid,s,21)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:21] ExecIf("PJSIP/206-00000878", "1?Set(CALLERID(all)=<+14055737881>)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf("PJSIP/206-00000878", "0?Set(CALLERID(all)=)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:23] ExecIf("PJSIP/206-00000878", "0?Set(CALLERID(all)=)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:24] ExecIf("PJSIP/206-00000878", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:25] ExecIf("PJSIP/206-00000878", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:26] Set("PJSIP/206-00000878", "CDR(outbound_cnum)=+14055737881") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-outbound-callerid:27] Set("PJSIP/206-00000878", "CDR(outbound_cnam)=") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:14] GosubIf("PJSIP/206-00000878", "0?sub-flp-12,s,1()") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:15] Set("PJSIP/206-00000878", "OUTNUM=+16822376643") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:16] Set("PJSIP/206-00000878", "custom=PJSIP") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf("PJSIP/206-00000878", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:18] ExecIf("PJSIP/206-00000878", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:19] Macro("PJSIP/206-00000878", "dialout-trunk-predial-hook,") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("PJSIP/206-00000878", "") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:20] GotoIf("PJSIP/206-00000878", "0?bypass,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:21] ExecIf("PJSIP/206-00000878", "1?Set(CONNECTEDLINE(num,i)=+16822376643)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:22] ExecIf("PJSIP/206-00000878", "1?Set(CONNECTEDLINE(name,i)=CID:+14055737881)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:23] ExecIf("PJSIP/206-00000878", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)+14055737881)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:24] GotoIf("PJSIP/206-00000878", "0?customtrunk") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:25] Dial("PJSIP/206-00000878", "PJSIP/+16822376643@Twilio_PJSip_US1_Virginia,300,Tb(func-apply-sipheaders^s^1,(12))") in new stack
[2019-06-11 11:50:46] ERROR[36065] res_pjsip.c: Endpoint 'Twilio_PJSip_US1_Virginia': Could not create dialog to invalid URI 'Twilio_PJSip_US1_Virginia'. Is endpoint registered and reachable?
[2019-06-11 11:50:46] ERROR[36065] chan_pjsip.c: Failed to create outgoing session to endpoint 'Twilio_PJSip_US1_Virginia'
[2019-06-11 11:50:46] WARNING[39303][C-00000399] app_dial.c: Unable to create channel of type 'PJSIP' (cause 3 - No route to destination)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:26] NoOp("PJSIP/206-00000878", "Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 3") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s@macro-dialout-trunk:27] GotoIf("PJSIP/206-00000878", "0?continue,1:s-CHANUNAVAIL,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set("PJSIP/206-00000878", "RC=3") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto("PJSIP/206-00000878", "3,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-dialout-trunk,3,1)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [3@macro-dialout-trunk:1] Goto("PJSIP/206-00000878", "continue,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (macro-dialout-trunk,continue,1)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [continue@macro-dialout-trunk:1] NoOp("PJSIP/206-00000878", "TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 3 - failing through to other trunks") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [continue@macro-dialout-trunk:2] ExecIf("PJSIP/206-00000878", "1?Set(CALLERID(number)=206)") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [16822376643@from-internal:9] Set("PJSIP/206-00000878", "CALLERID(all)="Doug" <206>") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [16822376643@from-internal:10] Set("PJSIP/206-00000878", "_KEEPCID=TRUE") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [16822376643@from-internal:11] Goto("PJSIP/206-00000878", "play-system-recording,6,1") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx_builtins.c: Goto (play-system-recording,6,1)
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [6@play-system-recording:1] Answer("PJSIP/206-00000878", "") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] pbx.c: Executing [6@play-system-recording:2] Playback("PJSIP/206-00000878", "custom/outboundcongestion") in new stack
[2019-06-11 11:50:46] VERBOSE[39303][C-00000399] file.c: <PJSIP/206-00000878> Playing 'custom/outboundcongestion.slin' (language 'en')
[2019-06-11 11:50:53] VERBOSE[39303][C-00000399] pbx.c: Executing [6@play-system-recording:3] Hangup("PJSIP/206-00000878", "") in new stack
[2019-06-11 11:50:53] VERBOSE[39303][C-00000399] pbx.c: Spawn extension (play-system-recording, 6, 3) exited non-zero on 'PJSIP/206-00000878'

I also found this in an older log. I don’t know the full context though.
It’s a slightly different message so maybe it’s helpful.

[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-outbound-callerid:21] ExecIf("PJSIP/202-00000367", "1?Set(CALLERID(all)=&lt;+14055737881&gt;)") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf("PJSIP/202-00000367", "0?Set(CALLERID(all)=)") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-outbound-callerid:23] ExecIf("PJSIP/202-00000367", "0?Set(CALLERID(all)=)") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-outbound-callerid:24] ExecIf("PJSIP/202-00000367", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-outbound-callerid:25] ExecIf("PJSIP/202-00000367", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-outbound-callerid:26] Set("PJSIP/202-00000367", "CDR(outbound_cnum)=+14055737881") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-outbound-callerid:27] Set("PJSIP/202-00000367", "CDR(outbound_cnam)=") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:14] GosubIf("PJSIP/202-00000367", "0?sub-flp-11,s,1()") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:15] Set("PJSIP/202-00000367", "OUTNUM=+14797187546") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:16] Set("PJSIP/202-00000367", "custom=PJSIP") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf("PJSIP/202-00000367", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:18] ExecIf("PJSIP/202-00000367", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:19] Macro("PJSIP/202-00000367", "dialout-trunk-predial-hook,") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("PJSIP/202-00000367", "") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:20] GotoIf("PJSIP/202-00000367", "0?bypass,1") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:21] ExecIf("PJSIP/202-00000367", "1?Set(CONNECTEDLINE(num,i)=+14797187546)") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:22] ExecIf("PJSIP/202-00000367", "1?Set(CONNECTEDLINE(name,i)=CID:+14055737881)") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:23] ExecIf("PJSIP/202-00000367", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)+14055737881)") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:24] GotoIf("PJSIP/202-00000367", "0?customtrunk") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:25] Dial("PJSIP/202-00000367", "PJSIP/+14797187546@Twilio_PJSip_US2_Oregon,300,Tb(func-apply-sipheaders^s^1,(11))") in new stack
[2019-05-08 13:59:25] ERROR[36065] res_pjsip.c: Endpoint 'Twilio_PJSip_US2_Oregon': Could not create dialog to invalid URI 'Twilio_PJSip_US2_Oregon'. Is endpoint registered and reachable?
[2019-05-08 13:59:25] ERROR[36065] chan_pjsip.c: Failed to create outgoing session to endpoint 'Twilio_PJSip_US2_Oregon'
[2019-05-08 13:59:25] WARNING[45208][C-00000181] app_dial.c: Unable to create channel of type 'PJSIP' (cause 3 - No route to destination)
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:26] NoOp("PJSIP/202-00000367", "Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 3") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx.c: Executing [s@macro-dialout-trunk:27] GotoIf("PJSIP/202-00000367", "0?continue,1:s-CHANUNAVAIL,1") in new stack
[2019-05-08 13:59:25] VERBOSE[45208][C-00000181] pbx_builtins.c: Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)

Sounds like a problem with your firewall timing the NAT session out, or the NAT settings in your system aren’t correct. Search the forum for “30 seconds” and you will that this is a common problem, but has several different possible solutions based on how the system is set up.

Firewall settings:

The Trunk Qualify Frequency is set to 5 seconds, so it doesn’t seem like the UDP stream should be timing out in the firewall since the UDP Other is 60 seconds and the UDP Stream is at 180 seconds.

Are there additional settings I should check?

Yeah - lots. You’ll need to check the Asterisk server to see how often it make sure the port is ‘reopened’. You’ll also need to make sure that your NAT settings for the connection (in your SIP setup) are correct. This isn’t a “one size fits all” solution set. There are many different things that could lead to this. Your firewall (which doesn’t apparently have an model information, or you would have absolutely included it) may be part of the problem, or not, but there are several things that can interact to cause this.

Look through the forum - we see variations on this at least once a week and there are easily a half dozen things that it could be. Details also don’t hurt - version numbers, manufacturers, PJ-SIP vs. Chan-SIP, etc. are all details that make is easier us to help you. Right now, you question is very generic, so you are going to get generic answers.

Thanks for the quick reply. I am for sure reading and reading to find other helpful posts and have been trying various combinations of suggestions within them for the last four months.

From the Advanced Settings page:
SIP nat: no

From the SIP Settings page General SIP Settings section:
External Address: my ipv4 public IP
Local Networks: 192.168.100.0 / 24 (the PreePBX server and all phones are in this network)
RTP Port Ranges: 10,000 - 20,000 (this range is forwarded in the firewall from each Twilio IP address to the FreePBX server IP address)
RTP Checksums: yes
Strick RTP: yes
RTP Timeout: 30
RTP Hold Timeout: 300
RTP Keep Alive: 5

Firewall with latest firmware and software: Ubiquiti UniFi Security Gateway 4P
Firewall Port forwarding setup:


All forwards are both TCP and UDP.

Two trunks using PJ-SIP. Twilio has an Oregon and a Virginia location, so I made one trunk for each.
From the Trunk → pjsip Settings → General page:
Authentication: Outbound
Registration: None (since we have a static IP, and Twilio has static IPs)
Context: from-pstn-e164-us
From the Trunk → pjsip Settings → Advanced page:
DTMF Mode: RFC 4733
Permanent Auth Rejection: Yes
Forbidden Retry Interval: 10
Fatal Retry Interval: 0
General Retry Interval: 15
Expiration: 3600
Max Retries: 1000000
Qualify Frequency: 5
Outbound Proxy: blank

What else to check?

Should probably be Yes.

  • Instead of two trunks, just use one (since you’re using PJ-SIP) and add all of the IP addresses in the Additional Addresses box.

  • Change your Media ports to be open to all from 10000-20000 and forward all of them to your 192.168.100.2 server.

  • Should your "Twilio to FreePBX - Virginia (Media) 2 connection be from 34.203.x.x? The rest of your Twilio connections are on ‘54.x.x.x’.

Changed. A short test call still works. My users will report back if the issue reoccurs. Since the issue is random, I can’t immediately tell if that solved it.

Where should the second address be entered? Here are my settings:


The two trunks are identicle accept for the localized SIP Server URL: us2 or us1. There is only one Outbound Route, which lists both Trunks:

The firewall was set like this for about two months with no change in results.

It is dissimilar than all the others that start with 54.x.x.x, but it is correct. See the Twilio IP address whitelist here.

Qualify Freq of 5 seconds is probably too short. Up that to 30-60 seconds see if things improve

We have run Qualify Frequency at 60, 30, 15, and now 5. No change.

Ran with this set to Yes since yesterday. No change.

Have you checked with Twilio to make sure they’re not blocking you for sending SIP options requests every 5 seconds? :smiley:

I would not be surprised to learn this had nothing to do with the PBX config and was some manner of network issue. Have you had SIP traversing this WAN edge successfully before, or is this a new setup?

Port forwarding looks right for Twilio US1/US2. Just curious, can you and/or have you tried 1:1 NAT?

I have not checked. But we have run with this at multiple intervals with the same results, so I don’t think they are blocking. But I will ask them anyway. I’ve upped it back to 25 just to give it a go again.

I’m not sure what you mean by “SIP traversing this WAN edge successfully before”. If you mean, have we ever gotten this setup to work before, then yes. It works right now…most of the time. That’s one of the main issues - we are on a call, everything is great, then all the sudden the Twilio endpoint “is now Unreachable”. When that happens, we still hear the other party, but they do not hear us. If they don’t hang up, our outgoing voice picks back up in ~10 - ~25 seconds then all is good again.

We have no done 1:1 NAT. As far as I understand, we would need to buy another static IP from our ISP, and reconfigure our network. I could try that if there are no other suggestions.

Mostly what I was curious about was is this a new setup that’s never worked consistently, or a setup that’s previously worked consistently and suddenly started behaving in this erratic fashion you are describing.

@AllianceDoug I’m not sure why no one has asked for this but you need an actual SIP debug for this. Showing stuff from the full log doesn’t do jack for troubleshooting these types of issues.

You need to get a pcap or run pjsip set logger on because we need to see the actual SIP messaging that is being sent during all this. What the signaling is, what happens when the call goes dead for that short time, if there are RE-Invites being sent, if the SDP is being updated. All that.

So you’ll need to run this and try to catch the issue.

IMO, this problem is caused by intermittent loss of outbound connectivity from PBX to internet. It’s just too much of a coincidence that two widely separated servers become unreachable at the same time that outbound RTP to Twilio media server is lost.

And, I’m reasonably sure that the trouble is unrelated to the PBX machine, because during the outage media flowing in from the trunk is successfully sent out to the extension.

The Twilio SIP servers do not block ICMP echo, so you can ping them. I would start up three continuously running pings: one to the USG LAN address (I assume it’s 192.168.100.1), one to the first ISP gateway (first external address that appears in a traceroute), and one to e.g. 54.172.60.0 .

After an unreachable is logged or audio dropout occurs, look for which of these pings shows packet loss (ping output should be redirected to a file so it’s easy to look back).

Also running the three pings on a workstation or different server (on the same LAN) would show whether the problem was unrelated to the PBX.

Who is your ISP? How connected (cable, fiber, etc.)? Is the modem bridged, or are you using an ISP-supplied gateway? What networking equipment, if any, is in the path from PBX to USG? From USG to modem?

Set up six months ago and always exhibited this behavior.

Thanks for the idea. I don’t know how to do this but will start looking it up and post when I get it figured out.

I ran and logged with timestamp one ping every seven seconds as you mentioned for 20 hours. There were many occurrences of dropped audio and many many Reachable/Unreachable events during that period. Only one single ping was not returned. So I don’t think general internet connectivity is the issue.

Cox Communications connected over a HFC network (Hybrid Fiber Coax) with Coax terminated in my building. Modem is not bridged. The modem is provided by the ISP and is a new DOCSIS 3.1 Motorola unit.

ISP → Motorola Modem → Ubiquiti USG-PRO-4 (Gateway/Router) → Ubiquiti UniFi Switch 16 POE-150W (dedicated to phone network) → FreePBX VM on Windows Server (with it’s own dedicated Ethernet from the server)

Checked. Twilio is not blocking due to frequent SIP Options. The Qualify Frequency is currently set at 25.

As another piece of information, I took a block of 96 Reachable/Unreachable events (four hours worth) from overnight that had nothing else going on in between them to gather some simple statistics. This shows how the system stayed in each state before moving to the other state. Here are the results:

Twilio%20Reachable%20Unreachable%20Stats

Any additional ideas are appreciated. Thank you.

I suspect mischief from your ‘modem’ (which, if not bridged, is actually a router over which you have little control).

An easy test is to start a tcpdump capture on the PBX, wait for at least one unreachable occurrence, stop capture, move the file to your PC and analyze it with Wireshark. If you see OPTIONS requests going out and replies not coming back, then we must look at the network. (tcpdump captures are ahead of the software firewall for incoming packets and after the firewall for outgoing; i.e. they represent what is sent and received on the wire.)

If the above test points to a network issue, the next step is to capture on network hardware. One possibility is plugging a PC into a spare port on the US-24, use its port mirroring capability to send a copy of all traffic on the router port to the PC, capture and analyze with Wireshark. There are also packet capture options in the USG (I believe it has tcpdump built in).

If it’s bad at the switch (valid OPTIONS going out and no replies received), then IMO the modem is the most likely culprit. Can you put it in bridge mode (perhaps with Cox assistance)? Or, can you substitute a modem that is inherently bridged (one with only a single Ethernet port)? Are there any settings in the gateway that may be relevant, e.g. a SIP ALG setting you can disable?

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