Sporadic "All circuits are busy" or other dropped calls

MSchub · February 7, 2023, 5:02pm

I’m stumped on this, and couldn’t locate any other relevant posts.

Working FreePBX 15.0.29, Asterisk 16.20.0 installation, no configuration changes made. It was working consistently, now it isn’t. Only one outbound trunk - PJSIP/Twilio.

Failure #1: I dial a number and it fails, then I hang up and dial it again and it succeeds.

-- Executing [s@macro-dialout-trunk:36] Dial("PJSIP/501-00000100", "PJSIP/+18882345678@Twilio,300,Tb(func-apply-sipheaders^s^1,(1))U(sub-send-obroute-email^+18882345678^18882345678^1^1675786772^^+12345678901)") in new stack
-- [2023-02-07 11:19:32] ERROR[20371]: res_pjsip.c:3703 ast_sip_create_dialog_uac: Endpoint 'Twilio': Could not create dialog to invalid URI 'Twilio'.  Is endpoint registered and reachable?
-- [2023-02-07 11:19:32] ERROR[20371]: chan_pjsip.c:2628 request: Failed to create outgoing session to endpoint 'Twilio'
-- [2023-02-07 11:19:32] WARNING[12847][C-0000009a]: app_dial.c:2584 dial_exec_full: Unable to create channel of type 'PJSIP' (cause 3 - No route to destination)

But then, I can try again to the exact same number in the very next call and it works:

-- Executing [s@macro-dialout-trunk:36] Dial("PJSIP/501-00000101", "PJSIP/+18882345678@Twilio,300,Tb(func-apply-sipheaders^s^1,(1))U(sub-send-obroute-email^+18882345678^18882345678^1^1675786803^^+12345678901)") in new stack
    -- PJSIP/Twilio-00000102 Internal Gosub(func-apply-sipheaders,s,1(1)) start

When this occurs, I get the all-circuits-busy-now message.

Failure 2: I hear a ring and then a disconnect with no message, and the call logs aren’t as clear as what I posted above. I didn’t post those here (yet) to keep the initial topic as clean as possible and to address this problem first.

Both started happening at about the same time, so they could very well be related.

dobrosavljevic · February 7, 2023, 5:28pm

If you look in the Twilio console under Monitor → Error → Error logs is Twilio reporting anything useful about the call?

If not you’ll also need to provide a SIP trace for failing calls to see what’s happening to the outbound traffic.

david55 · February 7, 2023, 5:35pm

I’d tend to take that at face value, i.e. you have a loss of internet connectivity or Twilio has.

MSchub · February 7, 2023, 5:39pm

In Failure 1, it never makes it to Twilio. That’s why I think it will be the easiest of the 2 failure types to fix.

In Failure 2, Twilio receives a FreePBX-initiated hangup “Reason: Q.850;cause=16” which is a generic catch-all when no reason is given.

I do have the SIP packet captures that correspond to the FreePBX log entries for Failure 2, but I don’t think the pcaps will show anything other than what I just posted above. I would think that the relevant info would be in the FreePBX log if that’s who is sending Twilio the hangup.

MSchub · February 7, 2023, 5:51pm

I thought that also, but ruled it out because I ran a terminal ping from FreePBX to my Twilio URI (it uses failover between different regional AWS datacenters) and it never dropped. Therefore, it eliminates both an internal layer 2 failure and an external routed failure.

dobrosavljevic · February 7, 2023, 5:52pm

In that case I would tend to agree with @david55. Look at your connectivity, it seems like the traffic never makes it to your SIP provider.

MSchub · February 7, 2023, 5:55pm

In that case I would tend to agree with @david55. Look at your connectivity, it seems like the traffic never makes it to your SIP provider.

I just replied to David:
I thought that also, but ruled it out because I ran a terminal ping from FreePBX to my Twilio URI (it uses failover between different regional AWS datacenters) and it never dropped. Therefore, it eliminates both an internal layer 2 failure and an external routed failure.

dobrosavljevic · February 7, 2023, 5:56pm

Ping traffic might be fine but it doesn’t seem like your SIP traffic ever makes it to Twilio and the only way to see what happens with your SIP traffic is to look at packet captures along the whole path that you have control over.

If you see the packets leaving your firewall but never getting to Twilio then there is an issue up stream form your connection that needs to be looked at.

MSchub · February 7, 2023, 6:14pm

10-4, you could very well be correct for Failure 1. I am not able to reproduce that problem at-will right now, so I have to leave the traces running until it materializes again and either confirm that this is the problem or rule it out.

For Failure 2 - where it IS getting to Twilio but then FreePBX terminates it without explanation - I’d rather not post the PCAP files because I cannot clean them for public display. I have compared two calls to each other:
Successful call

  == Spawn extension (from-pstn-e164-us, 17777777777, 1) exited non-zero on 'PJSIP/Twilio-000000ef'
    -- PJSIP/Twilio-000000ef Internal Gosub(func-apply-sipheaders,s,1(1)) complete GOSUB_RETVAL=
    -- Called PJSIP/+17777777777@Twilio
    -- PJSIP/Twilio-000000ef is ringing
       > 0x7fcf500d7d40 -- Strict RTP learning complete - Locking on source address 10.10.105.101:2252
  == Spawn extension (macro-dialout-trunk, s, 36) exited non-zero on 'PJSIP/101-000000ee' in macro 'dialout-trunk'
  == Spawn extension (from-internal, 17777777777, 11) exited non-zero on 'PJSIP/101-000000ee'
    -- Executing [h@from-internal:1] Macro("PJSIP/101-000000ee", "hangupcall") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("PJSIP/101-000000ee", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("PJSIP/101-000000ee", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] Hangup("PJSIP/101-000000ee", "") in new stack
  == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/101-000000ee' in macro 'hangupcall'
  == Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/101-000000ee'
    -- PJSIP/101-000000ee Internal Gosub(crm-hangup,s,1) start
    -- Executing [s@crm-hangup:1] NoOp("PJSIP/101-000000ee", "Sending Hangup to CRM") in new stack
    -- Executing [s@crm-hangup:2] NoOp("PJSIP/101-000000ee", "HANGUP CAUSE: 127") in new stack
    -- Executing [s@crm-hangup:3] ExecIf("PJSIP/101-000000ee", "0?Set(__CRM_VOICEMAIL=)") in new stack
    -- Executing [s@crm-hangup:4] NoOp("PJSIP/101-000000ee", "MASTER CHANNEL: 1675778765.280 = 1675778765.280") in new stack
    -- Executing [s@crm-hangup:5] GotoIf("PJSIP/101-000000ee", "0?return") in new stack
    -- Executing [s@crm-hangup:6] Set("PJSIP/101-000000ee", "__CRM_HANGUP=1") in new stack
    -- Executing [s@crm-hangup:7] AGI("PJSIP/101-000000ee", "agi://127.0.0.1/sangomacrm.agi") in new stack
    -- <PJSIP/101-000000ee>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
    -- Executing [s@crm-hangup:8] Return("PJSIP/101-000000ee", "") in new stack
  == Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/101-000000ee'
    -- PJSIP/101-000000ee Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=

Failed call

  == Spawn extension (from-pstn-e164-us, 18888888888, 1) exited non-zero on 'PJSIP/Twilio-000000eb'
    -- PJSIP/Twilio-000000eb Internal Gosub(func-apply-sipheaders,s,1(1)) complete GOSUB_RETVAL=
    -- Called PJSIP/+18888888888@Twilio
       > 0x7fcf4805fba0 -- Strict RTP learning after remote address set to: 54.172.60.59:15024
    -- PJSIP/Twilio-000000eb is making progress passing it to PJSIP/101-000000ea
    -- PJSIP/Twilio-000000eb answered PJSIP/101-000000ea
    -- PJSIP/Twilio-000000eb Internal Gosub(sub-send-obroute-email,s,1(+18888888888,18888888888,1,1675778418,,+15555555555)) start
    -- Executing [s@sub-send-obroute-email:1] GotoIf("PJSIP/Twilio-000000eb", "0?sendEmail") in new stack
    -- Executing [s@sub-send-obroute-email:2] NoOp("PJSIP/Twilio-000000eb", "email notifications disabled..exiting.") in new stack
    -- Executing [s@sub-send-obroute-email:3] Return("PJSIP/Twilio-000000eb", "") in new stack
  == Spawn extension (from-pstn-e164-us, , 1) exited non-zero on 'PJSIP/Twilio-000000eb'
    -- PJSIP/Twilio-000000eb Internal Gosub(sub-send-obroute-email,s,1(+18888888888,18888888888,1,1675778418,,+15555555555)) complete GOSUB_RETVAL=
    -- Channel PJSIP/Twilio-000000eb joined 'simple_bridge' basic-bridge <bcf5cb7d-eec6-4411-bc53-7679fee2fe38>
    -- Channel PJSIP/101-000000ea joined 'simple_bridge' basic-bridge <bcf5cb7d-eec6-4411-bc53-7679fee2fe38>
       > 0x7fcf48197160 -- Strict RTP learning complete - Locking on source address 10.10.105.101:2246
    -- Channel PJSIP/101-000000ea left 'simple_bridge' basic-bridge <bcf5cb7d-eec6-4411-bc53-7679fee2fe38>
  == Spawn extension (macro-dialout-trunk, s, 36) exited non-zero on 'PJSIP/101-000000ea' in macro 'dialout-trunk'
  == Spawn extension (from-internal, 18888888888, 11) exited non-zero on 'PJSIP/101-000000ea'
    -- Executing [h@from-internal:1] Macro("PJSIP/101-000000ea", "hangupcall") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("PJSIP/101-000000ea", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Channel PJSIP/Twilio-000000eb left 'simple_bridge' basic-bridge <bcf5cb7d-eec6-4411-bc53-7679fee2fe38>
    -- Executing [s@macro-hangupcall:3] ExecIf("PJSIP/101-000000ea", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] Hangup("PJSIP/101-000000ea", "") in new stack
  == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/101-000000ea' in macro 'hangupcall'
  == Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/101-000000ea'
    -- PJSIP/101-000000ea Internal Gosub(crm-hangup,s,1) start
    -- Executing [s@crm-hangup:1] NoOp("PJSIP/101-000000ea", "Sending Hangup to CRM") in new stack
    -- Executing [s@crm-hangup:2] NoOp("PJSIP/101-000000ea", "HANGUP CAUSE: 16") in new stack
    -- Executing [s@crm-hangup:3] ExecIf("PJSIP/101-000000ea", "0?Set(__CRM_VOICEMAIL=)") in new stack
    -- Executing [s@crm-hangup:4] NoOp("PJSIP/101-000000ea", "MASTER CHANNEL: 1675778418.276 = 1675778418.276") in new stack
    -- Executing [s@crm-hangup:5] GotoIf("PJSIP/101-000000ea", "0?return") in new stack
    -- Executing [s@crm-hangup:6] Set("PJSIP/101-000000ea", "__CRM_HANGUP=1") in new stack
    -- Executing [s@crm-hangup:7] AGI("PJSIP/101-000000ea", "agi://127.0.0.1/sangomacrm.agi") in new stack
    -- <PJSIP/101-000000ea>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
    -- Executing [s@crm-hangup:8] Return("PJSIP/101-000000ea", "") in new stack
  == Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/101-000000ea'
    -- PJSIP/101-000000ea Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=

In the successful call, you will see the HANGUP CAUSE 127 which is the user-initiated hangup from the extension (endpoint). In the failed, you see FreePBX generated HANGUP CAUSE 16, and I don’t see the reason why.

MSchub · February 7, 2023, 6:19pm

It looks like whatever happens during the “Gosub(func-apply-sipheaders,s,1(1)) complete GOSUB_RETVAL=” process is returning different information because the “Strict RTP Learning” processes are different from then on.

david55 · February 7, 2023, 7:15pm

Please use /var/log/asterisk/full, not a screenscrape, as the former contain timestamps which are important here.

The CLI command “pjsip set logger on” should allow you to get plain text protocol traces which you can redact, although even from wire shark, you should be able to see which side cleared the call an what reasons they gave.

MSchub · February 7, 2023, 7:37pm

I can see the termination in wireshark, but like I said previously, it’s just a generic “reason Q.850, cause 16, initiated by FPBX-15.0.24(16.20.0)”

I’ll enable pjsip logging and get the trace from the asterisk log like you requested.

MSchub · February 7, 2023, 7:53pm

Here is the full log from earlier, beginning at the point you quoted above:

[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] app_macro.c: Spawn extension (macro-dialout-trunk, s, 36) exited non-zero on 'PJSIP/101-000000ea' in macro 'dialout-trunk'
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Spawn extension (from-internal, 18008888888, 11) exited non-zero on 'PJSIP/101-000000ea'
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [h@from-internal:1] Macro("PJSIP/101-000000ea", "hangupcall") in new stack
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("PJSIP/101-000000ea", "1?theend") in new stack
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2023-02-07 09:00:38] VERBOSE[20180][C-0000008c] bridge_channel.c: Channel PJSIP/Twilio-000000eb left 'simple_bridge' basic-bridge <bcf5cb7d-eec6-4411-bc53-7679fee2fe38>
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("PJSIP/101-000000ea", "0?Set(CDR(recordingfile)=)") in new stack
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-hangupcall:4] Hangup("PJSIP/101-000000ea", "") in new stack
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'PJSIP/101-000000ea' in macro 'hangupcall'
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/101-000000ea'
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] app_stack.c: PJSIP/101-000000ea Internal Gosub(crm-hangup,s,1) start
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@crm-hangup:1] NoOp("PJSIP/101-000000ea", "Sending Hangup to CRM") in new stack
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@crm-hangup:2] NoOp("PJSIP/101-000000ea", "HANGUP CAUSE: 16") in new stack
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@crm-hangup:3] ExecIf("PJSIP/101-000000ea", "0?Set(__CRM_VOICEMAIL=)") in new stack
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@crm-hangup:4] NoOp("PJSIP/101-000000ea", "MASTER CHANNEL: 1675778418.276 = 1675778418.276") in new stack
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@crm-hangup:5] GotoIf("PJSIP/101-000000ea", "0?return") in new stack
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@crm-hangup:6] Set("PJSIP/101-000000ea", "__CRM_HANGUP=1") in new stack
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@crm-hangup:7] AGI("PJSIP/101-000000ea", "agi://127.0.0.1/sangomacrm.agi") in new stack
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] res_agi.c: <PJSIP/101-000000ea>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@crm-hangup:8] Return("PJSIP/101-000000ea", "") in new stack

david55 · February 7, 2023, 11:50pm

It’s already failed. The interesting times are the those from Dial to answer and from answer (or Dial) to failure.

MSchub · February 8, 2023, 1:29pm

Here is the rest of the call (truncated after the hangup):

[2023-02-07 09:00:18] VERBOSE[20371] netsock2.c: Using SIP RTP Audio TOS bits 184
[2023-02-07 09:00:18] VERBOSE[20371] netsock2.c: Using SIP RTP Audio TOS bits 184 in TCLASS field.
[2023-02-07 09:00:18] VERBOSE[20371] netsock2.c: Using SIP RTP Audio CoS mark 5
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [18008888888@from-internal:1] Macro("PJSIP/101-000000ea", "user-callerid,LIMIT,EXTERNAL,") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:1] Set("PJSIP/101-000000ea", "TOUCH_MONITOR=1675778418.276") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:2] Set("PJSIP/101-000000ea", "CHANCONTEXT=") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:3] Progress("PJSIP/101-000000ea", "") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:4] Set("PJSIP/101-000000ea", "CHANCONTEXT=") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:5] Set("PJSIP/101-000000ea", "CHANEXTENCONTEXT=101-000000ea") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:6] Set("PJSIP/101-000000ea", "CHANEXTEN=101-000000ea") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:7] Set("PJSIP/101-000000ea", "CALLERID(number)=101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:8] Set("PJSIP/101-000000ea", "AMPUSER=101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:9] Set("PJSIP/101-000000ea", "HOTDESCKCHAN=101-000000ea") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:10] Set("PJSIP/101-000000ea", "HOTDESKEXTEN=101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:11] Set("PJSIP/101-000000ea", "HOTDESKCALL=0") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:12] ExecIf("PJSIP/101-000000ea", "0?Set(HOTDESKCALL=1)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:13] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERID(name)=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:14] GotoIf("PJSIP/101-000000ea", "0?report") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:15] ExecIf("PJSIP/101-000000ea", "1?Set(REALCALLERIDNUM=101)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:16] Set("PJSIP/101-000000ea", "AMPUSER=101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:17] GotoIf("PJSIP/101-000000ea", "0?limit") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:18] Set("PJSIP/101-000000ea", "AMPUSERCIDNAME=Fname Lname") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:19] ExecIf("PJSIP/101-000000ea", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:20] GotoIf("PJSIP/101-000000ea", "0?report") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:21] Set("PJSIP/101-000000ea", "AMPUSERCID=101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:22] Set("PJSIP/101-000000ea", "__DIAL_OPTIONS=HhTtr") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:23] Set("PJSIP/101-000000ea", "CALLERID(all)="Fname Lname" <101>") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:24] ExecIf("PJSIP/101-000000ea", "0?Set(CUSDIAL=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:25] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERID(all)="Fname Lname" <101>)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:26] GotoIf("PJSIP/101-000000ea", "0?limit") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:27] ExecIf("PJSIP/101-000000ea", "1?Set(GROUP(concurrency_limit)=101)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:28] ExecIf("PJSIP/101-000000ea", "0?Set(CHANNEL(language)=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:29] NoOp("PJSIP/101-000000ea", "Macro Depth is 1") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:30] GotoIf("PJSIP/101-000000ea", "1?report2:macroerror") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx_builtins.c: Goto (macro-user-callerid,s,31)
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:31] GotoIf("PJSIP/101-000000ea", "1?continue") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx_builtins.c: Goto (macro-user-callerid,s,50)
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:50] Set("PJSIP/101-000000ea", "CALLERID(number)=101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:51] Set("PJSIP/101-000000ea", "CALLERID(name)=Fname Lname") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:52] GotoIf("PJSIP/101-000000ea", "0?cnum") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:53] Set("PJSIP/101-000000ea", "CDR(cnam)=Fname Lname") in new stack
[2023-02-07 09:00:18] VERBOSE[13212] res_rtp_asterisk.c: 0x7fcf48197160 -- Strict RTP learning after remote address set to: 10.10.105.101:2246
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:54] Set("PJSIP/101-000000ea", "CDR(cnum)=101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-user-callerid:55] Set("PJSIP/101-000000ea", "CHANNEL(language)=en") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [18008888888@from-internal:2] Gosub("PJSIP/101-000000ea", "sub-record-check,s,1(out,18008888888,dontcare)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:1] GotoIf("PJSIP/101-000000ea", "0?initialized") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:2] Set("PJSIP/101-000000ea", "__REC_STATUS=INITIALIZED") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:3] Set("PJSIP/101-000000ea", "NOW=1675778418") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:4] Set("PJSIP/101-000000ea", "__DAY=07") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:5] Set("PJSIP/101-000000ea", "__MONTH=02") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:6] Set("PJSIP/101-000000ea", "__YEAR=2023") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:7] Set("PJSIP/101-000000ea", "__TIMESTR=20230207-090018") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:8] Set("PJSIP/101-000000ea", "__FROMEXTEN=101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:9] Set("PJSIP/101-000000ea", "__MON_FMT=wav") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:10] NoOp("PJSIP/101-000000ea", "Recordings initialized") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:11] ExecIf("PJSIP/101-000000ea", "0?Set(ARG3=dontcare)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:12] Set("PJSIP/101-000000ea", "REC_POLICY_MODE_SAVE=") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:13] ExecIf("PJSIP/101-000000ea", "0?Set(REC_STATUS=NO)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:14] GotoIf("PJSIP/101-000000ea", "3?checkaction") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx_builtins.c: Goto (sub-record-check,s,17)
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-record-check:17] GotoIf("PJSIP/101-000000ea", "1?sub-record-check,out,1") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx_builtins.c: Goto (sub-record-check,out,1)
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [out@sub-record-check:1] NoOp("PJSIP/101-000000ea", "Outbound Recording Check from 101 to 18008888888") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [out@sub-record-check:2] Set("PJSIP/101-000000ea", "RECMODE=dontcare") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [out@sub-record-check:3] ExecIf("PJSIP/101-000000ea", "1?Goto(routewins)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx_builtins.c: Goto (sub-record-check,out,7)
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [out@sub-record-check:7] Gosub("PJSIP/101-000000ea", "recordcheck,1(dontcare,out,18008888888)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("PJSIP/101-000000ea", "Starting recording check against dontcare") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("PJSIP/101-000000ea", "dontcare") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [recordcheck@sub-record-check:3] Return("PJSIP/101-000000ea", "") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [out@sub-record-check:8] Return("PJSIP/101-000000ea", "") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [18008888888@from-internal:3] ExecIf("PJSIP/101-000000ea", "0 ?Set(CDR(accountcode)=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [18008888888@from-internal:4] Set("PJSIP/101-000000ea", "_ROUTEID=1") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [18008888888@from-internal:5] Set("PJSIP/101-000000ea", "_ROUTENAME=Twilio") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [18008888888@from-internal:6] Set("PJSIP/101-000000ea", "MOHCLASS=default") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [18008888888@from-internal:7] Set("PJSIP/101-000000ea", "_CALLERIDNAMEINTERNAL=Fname Lname") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [18008888888@from-internal:8] Set("PJSIP/101-000000ea", "_CALLERIDNUMINTERNAL=101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [18008888888@from-internal:9] Set("PJSIP/101-000000ea", "_EMAILNOTIFICATION=FALSE") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [18008888888@from-internal:10] Set("PJSIP/101-000000ea", "_NODEST=") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [18008888888@from-internal:11] Macro("PJSIP/101-000000ea", "dialout-trunk,1,+18008888888,,off") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:1] Set("PJSIP/101-000000ea", "DIAL_TRUNK=1") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:2] ExecIf("PJSIP/101-000000ea", "0?Set(DIAL_OPTIONS=Hhtr)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:3] GosubIf("PJSIP/101-000000ea", "0?sub-pincheck,s,1()") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:4] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERID(num)=101)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:5] GotoIf("PJSIP/101-000000ea", "0?disabletrunk,1") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:6] Set("PJSIP/101-000000ea", "DIAL_NUMBER=+18008888888") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:7] Set("PJSIP/101-000000ea", "DIAL_TRUNK_OPTIONS=HhTtr") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:8] Set("PJSIP/101-000000ea", "OUTBOUND_GROUP=OUT_1") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:9] Set("PJSIP/101-000000ea", "DIAL_TRUNK_OPTIONS=T") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:10] GotoIf("PJSIP/101-000000ea", "1?nomax") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx_builtins.c: Goto (macro-dialout-trunk,s,12)
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:12] GotoIf("PJSIP/101-000000ea", "0?skipoutcid") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:13] Macro("PJSIP/101-000000ea", "outbound-callerid,1") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:1] NoOp("PJSIP/101-000000ea", "101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:2] NoOp("PJSIP/101-000000ea", "") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:3] NoOp("PJSIP/101-000000ea", "all") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:4] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERPRES(name-pres)=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:5] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERPRES(num-pres)=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:6] Set("PJSIP/101-000000ea", "HOTDESCKCHAN=101-000000ea") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:7] Set("PJSIP/101-000000ea", "HOTDESKEXTEN=101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:8] Set("PJSIP/101-000000ea", "HOTDESKCALL=0") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:9] ExecIf("PJSIP/101-000000ea", "0?Set(HOTDESKCALL=1)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:10] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERID(name)=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:11] Set("PJSIP/101-000000ea", "ALLOWTHISROUTE=NO") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:12] ExecIf("PJSIP/101-000000ea", "0?Set(ALLOWTHISROUTE=YES)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:13] ExecIf("PJSIP/101-000000ea", "0?Hangup()") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:14] ExecIf("PJSIP/101-000000ea", "0?Set(REALCALLERIDNUM=101)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:15] ExecIf("PJSIP/101-000000ea", "0?Set(AMPUSER=101)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:16] GotoIf("PJSIP/101-000000ea", "1?normcid") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx_builtins.c: Goto (macro-outbound-callerid,s,20)
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:20] Set("PJSIP/101-000000ea", "USEROUTCID=") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:21] Set("PJSIP/101-000000ea", "EMERGENCYCID=") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:22] ExecIf("PJSIP/101-000000ea", "0?Set(SCDEXT=YES)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:23] ExecIf("PJSIP/101-000000ea", "0?Set(EMERGENCYCID=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:24] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERID(name)=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:25] ExecIf("PJSIP/101-000000ea", "0?Set(EMERGENCYCID=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:26] Set("PJSIP/101-000000ea", "TRUNKOUTCID=<+18755555555>") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:27] GotoIf("PJSIP/101-000000ea", "1?trunkcid") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx_builtins.c: Goto (macro-outbound-callerid,s,33)
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:33] ExecIf("PJSIP/101-000000ea", "1?Set(CALLERID(all)=<+18755555555>)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:34] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERID(all)=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:35] ExecIf("PJSIP/101-000000ea", "1?Set(CALLERID(all)=<+18755555555>)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:36] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERID(all)=101)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:37] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERID(all)=101)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:38] Set("PJSIP/101-000000ea", "TIOHIDE=no") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:39] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:40] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:41] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERPRES(name-pres)=prohib_passed_screen)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:42] ExecIf("PJSIP/101-000000ea", "0?Set(CALLERPRES(num-pres)=prohib_passed_screen)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:43] Set("PJSIP/101-000000ea", "CDR(outbound_cnum)=+18755555555") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-outbound-callerid:44] Set("PJSIP/101-000000ea", "CDR(outbound_cnam)=") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:14] GosubIf("PJSIP/101-000000ea", "0?sub-flp-1,s,1()") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:15] Set("PJSIP/101-000000ea", "OUTNUM=+18008888888") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:16] Set("PJSIP/101-000000ea", "custom=PJSIP") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf("PJSIP/101-000000ea", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)T)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:18] ExecIf("PJSIP/101-000000ea", "0?Set(DIAL_TRUNK_OPTIONS=TM(confirm))") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:19] GotoIf("PJSIP/101-000000ea", "1?gocall") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx_builtins.c: Goto (macro-dialout-trunk,s,21)
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:21] Macro("PJSIP/101-000000ea", "dialout-trunk-predial-hook,") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("PJSIP/101-000000ea", "") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:22] GotoIf("PJSIP/101-000000ea", "0?skipcrm") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:23] Set("PJSIP/101-000000ea", "__CRM_DIRECTION=OUTBOUND") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:24] Set("PJSIP/101-000000ea", "__CRM_DESTINATION=+18008888888") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:25] Set("PJSIP/101-000000ea", "__CRM_SOURCE=101") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:26] AGI("PJSIP/101-000000ea", "agi://127.0.0.1/sangomacrm.agi") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] res_rtp_asterisk.c: 0x7fcf48197160 -- Strict RTP switching to RTP target address 10.10.105.101:2246 as source
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] res_agi.c: <PJSIP/101-000000ea>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:27] Set("PJSIP/101-000000ea", "CHANNEL(hangup_handler_push)=crm-hangup,s,1") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:28] NoOp("PJSIP/101-000000ea", "CRM Finished") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:29] GotoIf("PJSIP/101-000000ea", "0?bypass,1") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:30] ExecIf("PJSIP/101-000000ea", "1?Set(CONNECTEDLINE(num,i)=+18008888888)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:31] ExecIf("PJSIP/101-000000ea", "1?Set(CONNECTEDLINE(name,i)=CID:+18755555555)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:32] ExecIf("PJSIP/101-000000ea", "0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)+18755555555)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:33] GotoIf("PJSIP/101-000000ea", "0?customtrunk") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:34] ExecIf("PJSIP/101-000000ea", "0?Set(DIAL_TRUNK_OPTIONS=)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:35] Set("PJSIP/101-000000ea", "HASH(__SIPHEADERS,Alert-Info)=unset") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@macro-dialout-trunk:36] Dial("PJSIP/101-000000ea", "PJSIP/+18008888888@Twilio,300,Tb(func-apply-sipheaders^s^1,(1))U(sub-send-obroute-email^+18008888888^18008888888^1^1675778418^^+18755555555)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] app_stack.c: PJSIP/Twilio-000000eb Internal Gosub(func-apply-sipheaders,s,1(1)) start
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf("PJSIP/Twilio-000000eb", "0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp("PJSIP/Twilio-000000eb", "Applying SIP Headers to channel PJSIP/Twilio-000000eb") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:3] Set("PJSIP/Twilio-000000eb", "TECH=PJSIP") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:4] Set("PJSIP/Twilio-000000eb", "SIPHEADERKEYS=Alert-Info") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/Twilio-000000eb", "1") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:6] Set("PJSIP/Twilio-000000eb", "sipheader=unset") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:7] ExecIf("PJSIP/Twilio-000000eb", "0?SIPRemoveHeader(Alert-Info:)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:8] ExecIf("PJSIP/Twilio-000000eb", "1?Set(PJSIP_HEADER(remove,Alert-Info)=)") in new stack
[2023-02-07 09:00:18] ERROR[26890] res_pjsip_header_funcs.c: No headers had been previously added to this session.
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:9] ExecIf("PJSIP/Twilio-000000eb", "0?Set(sipheader=<http://127.0.0.1>;info=unset)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:10] ExecIf("PJSIP/Twilio-000000eb", "0?Set(sipheader=<http://127.0.0.1>unset)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:11] ExecIf("PJSIP/Twilio-000000eb", "0?SIPAddHeader(Alert-Info:unset)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:12] ExecIf("PJSIP/Twilio-000000eb", "0?Set(PJSIP_HEADER(add,Alert-Info)=unset)") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:13] EndWhile("PJSIP/Twilio-000000eb", "") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:5] While("PJSIP/Twilio-000000eb", "0") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@func-apply-sipheaders:14] Return("PJSIP/Twilio-000000eb", "") in new stack
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] app_stack.c: Spawn extension (from-pstn-e164-us, 18008888888, 1) exited non-zero on 'PJSIP/Twilio-000000eb'
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] app_stack.c: PJSIP/Twilio-000000eb Internal Gosub(func-apply-sipheaders,s,1(1)) complete GOSUB_RETVAL=
[2023-02-07 09:00:18] VERBOSE[20168][C-0000008c] app_dial.c: Called PJSIP/+18008888888@Twilio
[2023-02-07 09:00:20] VERBOSE[843] res_rtp_asterisk.c: 0x7fcf4805fba0 -- Strict RTP learning after remote address set to: 54.172.60.59:15024
[2023-02-07 09:00:20] VERBOSE[20168][C-0000008c] app_dial.c: PJSIP/Twilio-000000eb is making progress passing it to PJSIP/101-000000ea
[2023-02-07 09:00:20] VERBOSE[20168][C-0000008c] app_dial.c: PJSIP/Twilio-000000eb answered PJSIP/101-000000ea
[2023-02-07 09:00:20] VERBOSE[20168][C-0000008c] app_stack.c: PJSIP/Twilio-000000eb Internal Gosub(sub-send-obroute-email,s,1(+18008888888,18008888888,1,1675778418,,+18755555555)) start
[2023-02-07 09:00:20] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-send-obroute-email:1] GotoIf("PJSIP/Twilio-000000eb", "0?sendEmail") in new stack
[2023-02-07 09:00:20] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-send-obroute-email:2] NoOp("PJSIP/Twilio-000000eb", "email notifications disabled..exiting.") in new stack
[2023-02-07 09:00:20] VERBOSE[20168][C-0000008c] pbx.c: Executing [s@sub-send-obroute-email:3] Return("PJSIP/Twilio-000000eb", "") in new stack
[2023-02-07 09:00:20] VERBOSE[20168][C-0000008c] app_stack.c: Spawn extension (from-pstn-e164-us, , 1) exited non-zero on 'PJSIP/Twilio-000000eb'
[2023-02-07 09:00:20] VERBOSE[20168][C-0000008c] app_stack.c: PJSIP/Twilio-000000eb Internal Gosub(sub-send-obroute-email,s,1(+18008888888,18008888888,1,1675778418,,+18755555555)) complete GOSUB_RETVAL=
[2023-02-07 09:00:20] VERBOSE[20180][C-0000008c] bridge_channel.c: Channel PJSIP/Twilio-000000eb joined 'simple_bridge' basic-bridge <bcf5cb7d-eec6-4411-bc53-7679fee2fe38>
[2023-02-07 09:00:20] VERBOSE[20168][C-0000008c] bridge_channel.c: Channel PJSIP/101-000000ea joined 'simple_bridge' basic-bridge <bcf5cb7d-eec6-4411-bc53-7679fee2fe38>
[2023-02-07 09:00:23] VERBOSE[20168][C-0000008c] res_rtp_asterisk.c: 0x7fcf48197160 -- Strict RTP learning complete - Locking on source address 10.10.105.101:2246
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] bridge_channel.c: Channel PJSIP/101-000000ea left 'simple_bridge' basic-bridge <bcf5cb7d-eec6-4411-bc53-7679fee2fe38>
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] app_macro.c: Spawn extension (macro-dialout-trunk, s, 36) exited non-zero on 'PJSIP/101-000000ea' in macro 'dialout-trunk'
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Spawn extension (from-internal, 18008888888, 11) exited non-zero on 'PJSIP/101-000000ea'
[2023-02-07 09:00:38] VERBOSE[20168][C-0000008c] pbx.c: Executing [h@from-internal:1] Macro("PJSIP/101-000000ea", "hangupcall") in new stack

system · March 11, 2023, 1:30pm

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