Inbound Calls Drop After 10 Seconds: Retransmission Error

luongjames · February 6, 2017, 8:00am

Hello - I’m new to FreePBX. I’ve searched the forums a bit here but haven’t found a good solution.

Here’s the situation:

Outbound Calls are Fine
Inbound Calls drop after about 10 seconds
Port Forwarding of 5060 and 10001-20000 enabled to FreePBX server
NAT Enabled

The error that I get is:

Really destroying SIP dialog '[email protected]:5160' Method: INVITE
[2017-02-06 15:39:55] WARNING[2187]: chan_sip.c:4061 retrans_pkt: Retransmission timeout reached on transmission [email protected] for seqno 20 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6399ms with no response
[2017-02-06 15:39:55] WARNING[2187]: chan_sip.c:4085 retrans_pkt: Hanging up call [email protected] - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions).
Really destroying SIP dialog '[email protected]:5160' Method: INVITE
Scheduling destruction of SIP dialog '[email protected]:5160' in 6400 ms (Method: INVITE)
  == Spawn extension (macro-dial, s, 19) exited non-zero on 'SIP/31507580-0000008d' in macro 'dial'
set_destination: Parsing <sip:[email protected]> for address/port to send to
set_destination: set destination to 10.0.3.7:5060
Reliably Transmitting (no NAT) to 10.0.3.7:5060:
BYE sip:[email protected] SIP/2.0
Via: SIP/2.0/UDP 10.0.3.10:5160;branch=z9hG4bK24a70dce
Max-Forwards: 70
From: "83860122" <sip:[email protected]:5160>;tag=as4a49841f
To: <sip:[email protected]>;tag=28E31BD7-687C9964
Call-ID: [email protected]:5160
CSeq: 103 BYE
User-Agent: FPBX-13.0.190.11(13.12.1)
X-Asterisk-HangupCause: No user responding
X-Asterisk-HangupCauseCode: 18
Content-Length: 0

I looked at the SIP DEBUG to look further at whats happening and this is what I get.

---
Retransmitting #3 (NAT) to 203.117.31.248:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 203.117.31.248;branch=z9hG4bK0152.156dbed7.0;received=203.117.31.248;rport=5060
Via: SIP/2.0/UDP 192.168.1.211:6889;rport=6889;branch=z9hG4bK21822095
Record-Route: <sip:203.117.31.248;r2=on;ftag=239907731;lr=on>
Record-Route: <sip:192.168.1.179;r2=on;ftag=239907731;lr=on>
From: 83860122 <sip:[email protected]:5060>;tag=239907731
To: <sip:[email protected]:5060>;tag=as6f96bf07
Call-ID: [email protected]
CSeq: 20 INVITE
Server: FPBX-13.0.190.11(13.12.1)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: <sip:[email protected]:5160>
Content-Type: application/sdp
Content-Length: 256

v=0
o=root 1450624280 1450624280 IN IP4 175.156.75.129
s=Asterisk PBX 13.12.1
c=IN IP4 175.156.75.129
t=0 0
m=audio 16748 RTP/AVP 0 110
a=rtpmap:0 PCMU/8000
a=rtpmap:110 telephone-event/8000
a=fmtp:110 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---

Would anyone have suggestions on how I can resolve this? I did notice that there is a private IP string within the error message 192.168.1.xxx. I am not using this subnet on any of my internal networks. Not sure how this got there, and whether this is affecting the problem at all.

cynjut · February 6, 2017, 9:26am

This isn’t normally a SIP problem, it’s usually a router/NAT problem.

IIRC, your UDP or NAT sessions are timing out too quickly. Check back through the archives and look for “UDP Timeout” and you should see your issue pretty quickly.

luongjames · February 12, 2017, 1:55am

Thanks Dave for the response.

I tried your suggestion and updated the NAT/router settings but it did not resolve the issue. It seems to be some issue on FreePBX.

I recalled that I had a lot of headache getting my FreePBX to work after I changed it’s IP address and moving it to another subnet. Eventually I did get it ‘working’, but I figured there were settings tied to the old IP and subnet buried somewhere that I did not know how to update.

Anyways, I just did a clean wipe and reinstalled, and everything works… Funny how that often does the trick.

luongjames · April 8, 2017, 8:44am

The fresh reinstall seemed to solve my problems last time around and things were working fine for about two months.

Now the problem is back for some unknowns reason. Nothing has changed other than actually a restart/reboot of the FreePBX server as I had to shutdown the machine to hook the server up to a battery. I am now back to square one.

Unfortunately, I don’t know what the logs looked like when things actually worked. But, the one thing that stands out to me is in the error I don’t actually have this 192.168.x.x. subnet on my network…

[2017-04-08 16:35:32] WARNING[1889] chan_sip.c: Retransmission timeout reached on transmission [email protected] for seqno 20 (Critical Response) --

Here’s more of the dump…

  [2017-04-08 16:35:24] VERBOSE[5862][C-00000052] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-08 16:35:24] VERBOSE[5862][C-00000052] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-08 16:35:24] VERBOSE[5862][C-00000052] app_stack.c: SIP/700-000000d9 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-04-08 16:35:24] VERBOSE[5862][C-00000052] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/700-000000d9", "Applying SIP Headers to channel") in new stack
[2017-04-08 16:35:24] VERBOSE[5862][C-00000052] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/700-000000d9", "SIPHEADERKEYS=") in new stack
[2017-04-08 16:35:24] VERBOSE[5862][C-00000052] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/700-000000d9", "0") in new stack
[2017-04-08 16:35:24] VERBOSE[5862][C-00000052] app_while.c: Jumping to priority 7
[2017-04-08 16:35:24] VERBOSE[5862][C-00000052] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/700-000000d9", "") in new stack
[2017-04-08 16:35:24] VERBOSE[5862][C-00000052] app_stack.c: Spawn extension (from-internal, 700, 1) exited non-zero on 'SIP/700-000000d9'
[2017-04-08 16:35:24] VERBOSE[5862][C-00000052] app_stack.c: SIP/700-000000d9 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-04-08 16:35:24] VERBOSE[5862][C-00000052] app_dial.c: Called SIP/700
[2017-04-08 16:35:25] VERBOSE[5862][C-00000052] app_dial.c: SIP/700-000000d9 is ringing
[2017-04-08 16:35:26] VERBOSE[5862][C-00000052] app_dial.c: SIP/700-000000d9 answered SIP/31507580-000000d8
[2017-04-08 16:35:26] VERBOSE[5863][C-00000052] bridge_channel.c: Channel SIP/700-000000d9 joined 'simple_bridge' basic-bridge <18cb15fa-1598-42fd-aeea-30ab77779aa4>
[2017-04-08 16:35:26] VERBOSE[5862][C-00000052] bridge_channel.c: Channel SIP/31507580-000000d8 joined 'simple_bridge' basic-bridge <18cb15fa-1598-42fd-aeea-30ab77779aa4>
[2017-04-08 16:35:32] WARNING[1889] chan_sip.c: Retransmission timeout reached on transmission [email protected] for seqno 20 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6400ms with no response
[2017-04-08 16:35:32] WARNING[1889] chan_sip.c: Hanging up call [email protected] - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions).
[2017-04-08 16:35:32] VERBOSE[5862][C-00000052] bridge_channel.c: Channel SIP/31507580-000000d8 left 'simple_bridge' basic-bridge <18cb15fa-1598-42fd-aeea-30ab77779aa4>
[2017-04-08 16:35:32] VERBOSE[5862][C-00000052] app_macro.c: Spawn extension (macro-dial-one, s, 51) exited non-zero on 'SIP/31507580-000000d8' in macro 'dial-one'
[2017-04-08 16:35:32] VERBOSE[5862][C-00000052] app_macro.c: Spawn extension (macro-exten-vm, s, 16) exited non-zero on 'SIP/31507580-000000d8' in macro 'exten-vm'
[2017-04-08 16:35:32] VERBOSE[5862][C-00000052] pbx.c: Spawn extension (ext-local, 700, 2) exited non-zero on 'SIP/31507580-000000d8'
[2017-04-08 16:35:32] VERBOSE[5862][C-00000052] pbx.c: Executing [h@ext-local:1] Macro("SIP/31507580-000000d8", "hangupcall,") in new stack
[2017-04-08 16:35:32] VERBOSE[5862][C-00000052] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/31507580-000000d8", "1?theend") in new stack
[2017-04-08 16:35:32] VERBOSE[5862][C-00000052] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2017-04-08 16:35:32] VERBOSE[5863][C-00000052] bridge_channel.c: Channel SIP/700-000000d9 left 'simple_bridge' basic-bridge <18cb15fa-1598-42fd-aeea-30ab77779aa4>
[2017-04-08 16:35:32] VERBOSE[5862][C-00000052] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/31507580-000000d8", "0?Set(CDR(recordingfile)=)") in new stack
[2017-04-08 16:35:32] VERBOSE[5862][C-00000052] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/31507580-000000d8", "") in new stack
[2017-04-08 16:35:32] VERBOSE[5862][C-00000052] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/31507580-000000d8' in macro 'hangupcall'
[2017-04-08 16:35:32] VERBOSE[5862][C-00000052] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/31507580-000000d8'

astbox · April 8, 2017, 1:44pm

Did you restored a backup from your previous installation or did you configure everything from scratch?

luongjames · April 8, 2017, 1:56pm

So here’s the basic timeline.

(1) Initial Error Occurred and I posted on FreePBX Forum
(2) Decided to clean wipe and restart with new configuration
(3) Everything fine for 2 months
(4) Restarted the FreePBX server and now the same error as observed in (1) is happening

frankb · April 8, 2017, 2:03pm

I would think that this is s networking issue of some sort.

astbox · April 8, 2017, 2:04pm

Ssh to your box and give the following command

ip addr

Post what you get. Also you don’t use raspberry pi as your “server”?

luongjames · April 8, 2017, 10:57pm

No… I don’t use raspberry pi. It’s a VM on an ESXi server.

Here’s the output

1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
    inet6 ::1/128 scope host
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP qlen 1000
    link/ether 00:0c:29:2b:9b:da brd ff:ff:ff:ff:ff:ff
    inet 10.0.3.10/24 brd 10.0.3.255 scope global eth0
    inet6 fe80::20c:29ff:fe2b:9bda/64 scope link
       valid_lft forever preferred_lft forever

I can’t find the 192.168.1.211 IP listed in the transmission timeout. Is there anyway to search all the configs for that IP?

dicko · April 8, 2017, 11:42pm

'You missed the interesting lines from when the call actually started, you just posted the bit where func-apply-sipheaders got messed but the [func-apply-sipheaders] context is not native to FreePBX. So you would have to paste that context too.

luongjames · April 9, 2017, 1:55am

Ok sorry about that. I thought I would try to filter out the noise, but that didn’t seem to work.

That section of the log is too large for one post so I will split into two. See below.

[2017-04-09 09:47:20] VERBOSE[1889][C-00000054] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 09:47:20] VERBOSE[1889][C-00000054] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@from-trunk:1] NoOp("SIP/31507580-000000df", "Catch-All DID Match - Found 600 - You probably want a DID for this.") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@from-trunk:2] Log("SIP/31507580-000000df", "WARNING,Friendly Scanner from 203.117.31.248;branch=z9hG4bK6ee2.44aca925.0") in new stack
[2017-04-09 09:47:20] WARNING[1582][C-00000054] Ext. 600: Friendly Scanner from 203.117.31.248;branch=z9hG4bK6ee2.44aca925.0
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@from-trunk:3] Set("SIP/31507580-000000df", "__FROM_DID=600") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@from-trunk:4] Goto("SIP/31507580-000000df", "ext-did,s,1") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (ext-did,s,1)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:1] Set("SIP/31507580-000000df", "__DIRECTION=INBOUND") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:2] Gosub("SIP/31507580-000000df", "sub-record-check,s,1(in,s,dontcare)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/31507580-000000df", "0?initialized") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:2] Set("SIP/31507580-000000df", "__REC_STATUS=INITIALIZED") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:3] Set("SIP/31507580-000000df", "NOW=1491702440") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:4] Set("SIP/31507580-000000df", "__DAY=09") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:5] Set("SIP/31507580-000000df", "__MONTH=04") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:6] Set("SIP/31507580-000000df", "__YEAR=2017") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:7] Set("SIP/31507580-000000df", "__TIMESTR=20170409-094720") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:8] Set("SIP/31507580-000000df", "__FROMEXTEN=unknown") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:9] Set("SIP/31507580-000000df", "__MON_FMT=wav") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/31507580-000000df", "Recordings initialized") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/31507580-000000df", "0?Set(ARG3=dontcare)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:12] Set("SIP/31507580-000000df", "REC_POLICY_MODE_SAVE=") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/31507580-000000df", "0?Set(REC_STATUS=NO)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/31507580-000000df", "2?checkaction") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/31507580-000000df", "1?sub-record-check,in,1") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (sub-record-check,in,1)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/31507580-000000df", "Inbound Recording Check to s") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [in@sub-record-check:2] Set("SIP/31507580-000000df", "FROMEXTEN=unknown") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/31507580-000000df", "8?Set(FROMEXTEN=83860122)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/31507580-000000df", "recordcheck,1(dontcare,in,s)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/31507580-000000df", "Starting recording check against dontcare") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/31507580-000000df", "dontcare") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/31507580-000000df", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [in@sub-record-check:5] Return("SIP/31507580-000000df", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:3] Gosub("SIP/31507580-000000df", "app-blacklist-check,s,1()") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/31507580-000000df", "0?blacklisted") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/31507580-000000df", "CALLED_BLACKLIST=1") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/31507580-000000df", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:4] ExecIf("SIP/31507580-000000df", "0?Set(__FROM_DID=s)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:5] Set("SIP/31507580-000000df", "CDR(did)=600") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:6] ExecIf("SIP/31507580-000000df", "0 ?Set(CALLERID(name)=83860122)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:7] Set("SIP/31507580-000000df", "__MOHCLASS=") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:8] Set("SIP/31507580-000000df", "__REVERSAL_REJECT=FALSE") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:9] GotoIf("SIP/31507580-000000df", "1?post-reverse-charge") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (ext-did,s,11)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:11] NoOp("SIP/31507580-000000df", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:12] Set("SIP/31507580-000000df", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:13] Set("SIP/31507580-000000df", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:14] Set("SIP/31507580-000000df", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:15] Set("SIP/31507580-000000df", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:16] NoOp("SIP/31507580-000000df", "CallerID Entry Point") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@ext-did:17] Goto("SIP/31507580-000000df", "ext-group,600,1") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (ext-group,600,1)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:1] GotoIf("SIP/31507580-000000df", "0?cid") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:2] PlayTones("SIP/31507580-000000df", "ring") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:3] Progress("SIP/31507580-000000df", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:4] Macro("SIP/31507580-000000df", "user-callerid,") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/31507580-000000df", "TOUCH_MONITOR=1491702440.223") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/31507580-000000df", "AMPUSER=83860122") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/31507580-000000df", "0?report") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/31507580-000000df", "1?Set(REALCALLERIDNUM=83860122)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/31507580-000000df", "AMPUSER=") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/31507580-000000df", "0?limit") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/31507580-000000df", "AMPUSERCIDNAME=") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/31507580-000000df", "1?report") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (macro-user-callerid,s,15)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:15] GotoIf("SIP/31507580-000000df", "0?continue") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:16] ExecIf("SIP/31507580-000000df", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:17] Set("SIP/31507580-000000df", "__TTL=64") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/31507580-000000df", "1?continue") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (macro-user-callerid,s,29)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:29] Set("SIP/31507580-000000df", "CALLERID(number)=83860122") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/31507580-000000df", "CALLERID(name)=83860122") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:31] GotoIf("SIP/31507580-000000df", "0?cnum") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:32] Set("SIP/31507580-000000df", "CDR(cnam)=83860122") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:33] Set("SIP/31507580-000000df", "CDR(cnum)=83860122") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-user-callerid:34] Set("SIP/31507580-000000df", "CHANNEL(language)=en") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:5] Macro("SIP/31507580-000000df", "blkvm-setifempty,") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/31507580-000000df", "1?init") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (macro-blkvm-setifempty,s,4)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-blkvm-setifempty:4] Set("SIP/31507580-000000df", "__BLKVM_CHANNEL=SIP/31507580-000000df") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-blkvm-setifempty:5] Set("SIP/31507580-000000df", "SHARED(BLKVM,SIP/31507580-000000df)=TRUE") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-blkvm-setifempty:6] Set("SIP/31507580-000000df", "GOSUB_RETVAL=TRUE") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/31507580-000000df", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:6] GotoIf("SIP/31507580-000000df", "1?skipov") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (ext-group,600,9)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:9] Set("SIP/31507580-000000df", "RRNODEST=") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:10] Set("SIP/31507580-000000df", "__NODEST=600") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:11] GosubIf("SIP/31507580-000000df", "0?sub-rgsetcid,s,1()") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:12] Gosub("SIP/31507580-000000df", "sub-record-check,s,1(rg,600,dontcare)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/31507580-000000df", "8?initialized") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (sub-record-check,s,10)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/31507580-000000df", "Recordings initialized") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/31507580-000000df", "0?Set(ARG3=dontcare)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:12] Set("SIP/31507580-000000df", "REC_POLICY_MODE_SAVE=") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/31507580-000000df", "0?Set(REC_STATUS=NO)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/31507580-000000df", "2?checkaction") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/31507580-000000df", "0?sub-record-check,rg,1") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:18] NoOp("SIP/31507580-000000df", "Generic rg Recording Check - 83860122 600") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:19] Gosub("SIP/31507580-000000df", "recordcheck,1(dontcare,rg,600)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/31507580-000000df", "Starting recording check against dontcare") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/31507580-000000df", "dontcare") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/31507580-000000df", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@sub-record-check:20] Return("SIP/31507580-000000df", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:13] Set("SIP/31507580-000000df", "RingGroupMethod=ringall") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [600@ext-group:14] Macro("SIP/31507580-000000df", "dial,20,Ttr,800-805-802-801") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:1] NoOp("SIP/31507580-000000df", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:2] ExecIf("SIP/31507580-000000df", "0?Set(ALERT_INFO=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:3] ExecIf("SIP/31507580-000000df", "0?Set(ALERT_INFO=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:4] ExecIf("SIP/31507580-000000df", "0?Set(ALERT_INFO=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:5] ExecIf("SIP/31507580-000000df", "0?Set(CHANNEL(musicclass)=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:6] AGI("SIP/31507580-000000df", "dialparties.agi") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Caller ID name is '83860122' number is '83860122'
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: CW Ignore is:
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: CF Ignore is:
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: CW IN_USE/BUSY is: 1
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Methodology of ring is 'ringall'
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Added extension 800 to extension map
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Added extension 805 to extension map
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Added extension 802 to extension map
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Added extension 801 to extension map
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Extension 800 cf is disabled
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Extension 805 cf is disabled
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Extension 802 cf is disabled
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Extension 801 cf is disabled
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Extension 800 do not disturb is disabled
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Extension 805 do not disturb is disabled
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Extension 802 do not disturb is disabled
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Extension 801 do not disturb is disabled
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: dbset CALLTRACE/800 to 83860122
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: dbset CALLTRACE/805 to 83860122
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: dbset CALLTRACE/802 to 83860122
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: dbset CALLTRACE/801 to 83860122
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: dialparties.agi: Filtered ARG3: 800-805-802-801

luongjames · April 9, 2017, 1:56am

Part II…

[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] res_agi.c: <SIP/31507580-000000df>AGI Script dialparties.agi completed, returning 0
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:9] NoOp("SIP/31507580-000000df", "Returned from dialparties with groups to dial") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:10] Set("SIP/31507580-000000df", "LOOPCNT=4") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:11] Set("SIP/31507580-000000df", "ITER=1") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:12] Set("SIP/31507580-000000df", "EXTTOCALL=800") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/31507580-000000df", "Working with 800") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/31507580-000000df", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/31507580-000000df", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:16] Set("SIP/31507580-000000df", "ITER=2") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/31507580-000000df", "1?ndloopbegin") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:12] Set("SIP/31507580-000000df", "EXTTOCALL=805") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/31507580-000000df", "Working with 805") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/31507580-000000df", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/31507580-000000df", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:16] Set("SIP/31507580-000000df", "ITER=3") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/31507580-000000df", "1?ndloopbegin") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:12] Set("SIP/31507580-000000df", "EXTTOCALL=802") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/31507580-000000df", "Working with 802") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/31507580-000000df", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/31507580-000000df", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:16] Set("SIP/31507580-000000df", "ITER=4") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/31507580-000000df", "1?ndloopbegin") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:12] Set("SIP/31507580-000000df", "EXTTOCALL=801") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/31507580-000000df", "Working with 801") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/31507580-000000df", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/31507580-000000df", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:16] Set("SIP/31507580-000000df", "ITER=5") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/31507580-000000df", "0?ndloopbegin") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:18] Macro("SIP/31507580-000000df", "dial-ringall-predial-hook,") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("SIP/31507580-000000df", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-dial:19] Dial("SIP/31507580-000000df", "SIP/800&SIP/805&SIP/802&SIP/801,20,trM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: SIP/800-000000e0 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/800-000000e0", "Applying SIP Headers to channel") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/800-000000e0", "SIPHEADERKEYS=") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/800-000000e0", "0") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_while.c: Jumping to priority 7
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/800-000000e0", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/800-000000e0'
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: SIP/800-000000e0 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: SIP/805-000000e1 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/805-000000e1", "Applying SIP Headers to channel") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/805-000000e1", "SIPHEADERKEYS=") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/805-000000e1", "0") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_while.c: Jumping to priority 7
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/805-000000e1", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/805-000000e1'
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: SIP/805-000000e1 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: SIP/802-000000e2 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/802-000000e2", "Applying SIP Headers to channel") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/802-000000e2", "SIPHEADERKEYS=") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/802-000000e2", "0") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_while.c: Jumping to priority 7
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/802-000000e2", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/802-000000e2'
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: SIP/802-000000e2 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: SIP/801-000000e3 Internal Gosub(func-apply-sipheaders,s,1) start
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/801-000000e3", "Applying SIP Headers to channel") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/801-000000e3", "SIPHEADERKEYS=") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/801-000000e3", "0") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_while.c: Jumping to priority 7
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/801-000000e3", "") in new stack
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/801-000000e3'
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_stack.c: SIP/801-000000e3 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_dial.c: Called SIP/800
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_dial.c: Called SIP/805
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_dial.c: Called SIP/802
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_dial.c: Called SIP/801
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_dial.c: SIP/801-000000e3 connected line has changed. Saving it until answer for SIP/31507580-000000df
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_dial.c: SIP/802-000000e2 connected line has changed. Saving it until answer for SIP/31507580-000000df
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_dial.c: SIP/805-000000e1 connected line has changed. Saving it until answer for SIP/31507580-000000df
[2017-04-09 09:47:20] VERBOSE[1582][C-00000054] app_dial.c: SIP/800-000000e0 connected line has changed. Saving it until answer for SIP/31507580-000000df
[2017-04-09 09:47:21] VERBOSE[1582][C-00000054] app_dial.c: SIP/805-000000e1 is ringing
[2017-04-09 09:47:21] VERBOSE[1582][C-00000054] app_dial.c: SIP/800-000000e0 is ringing
[2017-04-09 09:47:21] VERBOSE[1582][C-00000054] app_dial.c: SIP/801-000000e3 is ringing
[2017-04-09 09:47:21] VERBOSE[1582][C-00000054] app_dial.c: SIP/802-000000e2 is ringing
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] app_dial.c: SIP/800-000000e0 connected line has changed. Saving it until answer for SIP/31507580-000000df
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] app_dial.c: SIP/800-000000e0 answered SIP/31507580-000000df
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-auto-blkvm:1] Set("SIP/800-000000e0", "__MACRO_RESULT=") in new stack
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-auto-blkvm:2] Set("SIP/800-000000e0", "CFIGNORE=") in new stack
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-auto-blkvm:3] Set("SIP/800-000000e0", "MASTER_CHANNEL(CFIGNORE)=") in new stack
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-auto-blkvm:4] Set("SIP/800-000000e0", "FORWARD_CONTEXT=from-internal") in new stack
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-auto-blkvm:5] Set("SIP/800-000000e0", "MASTER_CHANNEL(FORWARD_CONTEXT)=from-internal") in new stack
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-auto-blkvm:6] Macro("SIP/800-000000e0", "blkvm-clr,") in new stack
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-blkvm-clr:1] Set("SIP/800-000000e0", "SHARED(BLKVM,SIP/31507580-000000df)=") in new stack
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-blkvm-clr:2] Set("SIP/800-000000e0", "GOSUB_RETVAL=") in new stack
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-blkvm-clr:3] MacroExit("SIP/800-000000e0", "") in new stack
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-auto-blkvm:7] ExecIf("SIP/800-000000e0", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(num))=800)") in new stack
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-auto-blkvm:8] ExecIf("SIP/800-000000e0", "0?Set(MASTER_CHANNEL(CONNECTEDLINE(name))=JL Desk)") in new stack
[2017-04-09 09:47:22] VERBOSE[1585][C-00000054] bridge_channel.c: Channel SIP/800-000000e0 joined 'simple_bridge' basic-bridge <cf4e34db-be4c-44fc-8e07-35661f36a5e3>
[2017-04-09 09:47:22] VERBOSE[1582][C-00000054] bridge_channel.c: Channel SIP/31507580-000000df joined 'simple_bridge' basic-bridge <cf4e34db-be4c-44fc-8e07-35661f36a5e3>
[2017-04-09 09:47:29] WARNING[1889] chan_sip.c: Retransmission timeout reached on transmission [email protected] for seqno 20 (Critical Response) -- See https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions
Packet timed out after 6399ms with no response
[2017-04-09 09:47:29] WARNING[1889] chan_sip.c: Hanging up call [email protected] - no reply to our critical packet (see https://wiki.asterisk.org/wiki/display/AST/SIP+Retransmissions).
[2017-04-09 09:47:29] VERBOSE[1582][C-00000054] bridge_channel.c: Channel SIP/31507580-000000df left 'simple_bridge' basic-bridge <cf4e34db-be4c-44fc-8e07-35661f36a5e3>
[2017-04-09 09:47:29] VERBOSE[1585][C-00000054] bridge_channel.c: Channel SIP/800-000000e0 left 'simple_bridge' basic-bridge <cf4e34db-be4c-44fc-8e07-35661f36a5e3>
[2017-04-09 09:47:29] VERBOSE[1582][C-00000054] app_macro.c: Spawn extension (macro-dial, s, 19) exited non-zero on 'SIP/31507580-000000df' in macro 'dial'
[2017-04-09 09:47:29] VERBOSE[1582][C-00000054] pbx.c: Spawn extension (ext-group, 600, 14) exited non-zero on 'SIP/31507580-000000df'
[2017-04-09 09:47:29] VERBOSE[1582][C-00000054] pbx.c: Executing [h@ext-group:1] Macro("SIP/31507580-000000df", "hangupcall,") in new stack
[2017-04-09 09:47:29] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/31507580-000000df", "1?theend") in new stack
[2017-04-09 09:47:29] VERBOSE[1582][C-00000054] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2017-04-09 09:47:29] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/31507580-000000df", "0?Set(CDR(recordingfile)=)") in new stack
[2017-04-09 09:47:29] VERBOSE[1582][C-00000054] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/31507580-000000df", "") in new stack
[2017-04-09 09:47:29] VERBOSE[1582][C-00000054] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/31507580-000000df' in macro 'hangupcall'
[2017-04-09 09:47:29] VERBOSE[1582][C-00000054] pbx.c: Spawn extension (ext-group, h, 1) exited non-zero on 'SIP/31507580-000000df'

cynjut · April 9, 2017, 2:16am

Do you see the error? It looks like someone has call forwarded line 800 to [email protected] and there’s no route to that phone, which makes sense since your local network is not on that non-routable network.

luongjames · April 9, 2017, 2:20am

I’ve seen that line for awhile, and I’ve posted about it above.

I’m just not sure how to resolve it because I don’t have that setting anywhere. I’ve dug around looking for it too.

cynjut · April 9, 2017, 2:27am

Have you checked in the phone on extension 800. It could be something left over from a time when your phone wasn’t yours?

luongjames · April 9, 2017, 2:32am

I did a clean wipe of the phone when I put it on this deployment.

I have another trunk that has the same problem, which is not part of the ring group. Maybe the logs there will help isolate some of the problems.

One very peculiar thing about this section of the logs is that it shows that SIP/31507580… but this line has a different number 31139303

I just checked the Trunk Settings and the 31139303 trunk has no information that the 31507580 one has. This is so bizarre.

[2017-04-09 10:26:29] VERBOSE[1889][C-00000056] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 10:26:29] VERBOSE[1889][C-00000056] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [700@from-trunk:1] GotoIf("SIP/31507580-000000e6", "1?ext-local,700,1:followme-check,700,1") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (ext-local,700,1)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [700@ext-local:1] Set("SIP/31507580-000000e6", "__RINGTIMER=15") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [700@ext-local:2] Macro("SIP/31507580-000000e6", "exten-vm,700,700,0,0,0") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-exten-vm:1] Macro("SIP/31507580-000000e6", "user-callerid,") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/31507580-000000e6", "TOUCH_MONITOR=1491704789.230") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/31507580-000000e6", "AMPUSER=83860122") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/31507580-000000e6", "0?report") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/31507580-000000e6", "1?Set(REALCALLERIDNUM=83860122)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/31507580-000000e6", "AMPUSER=") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/31507580-000000e6", "0?limit") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/31507580-000000e6", "AMPUSERCIDNAME=") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/31507580-000000e6", "1?report") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (macro-user-callerid,s,15)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:15] GotoIf("SIP/31507580-000000e6", "0?continue") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:16] ExecIf("SIP/31507580-000000e6", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:17] Set("SIP/31507580-000000e6", "__TTL=64") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/31507580-000000e6", "1?continue") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (macro-user-callerid,s,29)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:29] Set("SIP/31507580-000000e6", "CALLERID(number)=83860122") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/31507580-000000e6", "CALLERID(name)=83860122") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:31] GotoIf("SIP/31507580-000000e6", "0?cnum") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:32] Set("SIP/31507580-000000e6", "CDR(cnam)=83860122") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:33] Set("SIP/31507580-000000e6", "CDR(cnum)=83860122") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-user-callerid:34] Set("SIP/31507580-000000e6", "CHANNEL(language)=en") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-exten-vm:2] Set("SIP/31507580-000000e6", "RingGroupMethod=none") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-exten-vm:3] Set("SIP/31507580-000000e6", "__EXTTOCALL=700") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-exten-vm:4] Set("SIP/31507580-000000e6", "__PICKUPMARK=700") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-exten-vm:5] Set("SIP/31507580-000000e6", "RT=15") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-exten-vm:6] ExecIf("SIP/31507580-000000e6", "0?Macro(vm,700,DIRECTDIAL,)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-exten-vm:7] ExecIf("SIP/31507580-000000e6", "0?MacroExit()") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-exten-vm:8] Gosub("SIP/31507580-000000e6", "sub-record-check,s,1(exten,700,dontcare)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/31507580-000000e6", "0?initialized") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:2] Set("SIP/31507580-000000e6", "__REC_STATUS=INITIALIZED") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:3] Set("SIP/31507580-000000e6", "NOW=1491704789") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:4] Set("SIP/31507580-000000e6", "__DAY=09") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:5] Set("SIP/31507580-000000e6", "__MONTH=04") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:6] Set("SIP/31507580-000000e6", "__YEAR=2017") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:7] Set("SIP/31507580-000000e6", "__TIMESTR=20170409-102629") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:8] Set("SIP/31507580-000000e6", "__FROMEXTEN=83860122") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:9] Set("SIP/31507580-000000e6", "__MON_FMT=wav") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/31507580-000000e6", "Recordings initialized") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/31507580-000000e6", "0?Set(ARG3=dontcare)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:12] Set("SIP/31507580-000000e6", "REC_POLICY_MODE_SAVE=") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/31507580-000000e6", "0?Set(REC_STATUS=NO)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/31507580-000000e6", "5?checkaction") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/31507580-000000e6", "1?sub-record-check,exten,1") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (sub-record-check,exten,1)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:1] NoOp("SIP/31507580-000000e6", "Exten Recording Check between 83860122 and 700") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:2] Set("SIP/31507580-000000e6", "CALLTYPE=internal") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:3] ExecIf("SIP/31507580-000000e6", "0?Set(CALLTYPE=)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:4] Set("SIP/31507580-000000e6", "CALLEE=dontcare") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:5] ExecIf("SIP/31507580-000000e6", "0?Set(CALLEE=dontcare)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:6] GotoIf("SIP/31507580-000000e6", "0?callee") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:7] GotoIf("SIP/31507580-000000e6", "1?caller") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (sub-record-check,exten,13)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:13] Set("SIP/31507580-000000e6", "RECMODE=") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:14] ExecIf("SIP/31507580-000000e6", "1?Set(RECMODE=dontcare)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:15] ExecIf("SIP/31507580-000000e6", "1?Set(RECMODE=dontcare)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:16] Gosub("SIP/31507580-000000e6", "recordcheck,1(dontcare,internal,700)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/31507580-000000e6", "Starting recording check against dontcare") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/31507580-000000e6", "dontcare") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/31507580-000000e6", "") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [exten@sub-record-check:17] Return("SIP/31507580-000000e6", "") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-exten-vm:9] GotoIf("SIP/31507580-000000e6", "1?macrodial") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (macro-exten-vm,s,15)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-exten-vm:15] GosubIf("SIP/31507580-000000e6", "0?clrheader,1()") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-exten-vm:16] Macro("SIP/31507580-000000e6", "dial-one,15,Ttr,700") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:1] Set("SIP/31507580-000000e6", "DEXTEN=700") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:2] ExecIf("SIP/31507580-000000e6", "0?Set(EXTTOCALL=700)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:3] Set("SIP/31507580-000000e6", "DIALSTATUS_CW=") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:4] GosubIf("SIP/31507580-000000e6", "0?screen,1()") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:5] GosubIf("SIP/31507580-000000e6", "0?cf,1()") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:6] GotoIf("SIP/31507580-000000e6", "1?skip1") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (macro-dial-one,s,9)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:9] GotoIf("SIP/31507580-000000e6", "0?nodial") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:10] GotoIf("SIP/31507580-000000e6", "0?continue") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:11] Set("SIP/31507580-000000e6", "EXTHASCW=ENABLED") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:12] GotoIf("SIP/31507580-000000e6", "0?next1:cwinusebusy") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (macro-dial-one,s,24)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:24] GotoIf("SIP/31507580-000000e6", "0?next3:continue") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (macro-dial-one,s,26)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:26] GotoIf("SIP/31507580-000000e6", "0?nodial") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:27] GosubIf("SIP/31507580-000000e6", "1?dstring,1():dlocal,1()") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:1] Set("SIP/31507580-000000e6", "DSTRING=") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:2] Set("SIP/31507580-000000e6", "DEVICES=700") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:3] ExecIf("SIP/31507580-000000e6", "0?Return()") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:4] ExecIf("SIP/31507580-000000e6", "0?Set(DEVICES=00)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:5] Set("SIP/31507580-000000e6", "LOOPCNT=1") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:6] Set("SIP/31507580-000000e6", "ITER=1") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:7] Set("SIP/31507580-000000e6", "THISDIAL=SIP/700") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:8] GosubIf("SIP/31507580-000000e6", "1?zap2dahdi,1()") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [zap2dahdi@macro-dial-one:1] ExecIf("SIP/31507580-000000e6", "0?Return()") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [zap2dahdi@macro-dial-one:2] Set("SIP/31507580-000000e6", "NEWDIAL=") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [zap2dahdi@macro-dial-one:3] Set("SIP/31507580-000000e6", "LOOPCNT2=1") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [zap2dahdi@macro-dial-one:4] Set("SIP/31507580-000000e6", "ITER2=1") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [zap2dahdi@macro-dial-one:5] Set("SIP/31507580-000000e6", "THISPART2=SIP/700") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [zap2dahdi@macro-dial-one:6] ExecIf("SIP/31507580-000000e6", "0?Set(THISPART2=DAHDI/700)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [zap2dahdi@macro-dial-one:7] Set("SIP/31507580-000000e6", "NEWDIAL=SIP/700&") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [zap2dahdi@macro-dial-one:8] Set("SIP/31507580-000000e6", "ITER2=2") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [zap2dahdi@macro-dial-one:9] GotoIf("SIP/31507580-000000e6", "0?begin2") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [zap2dahdi@macro-dial-one:10] Set("SIP/31507580-000000e6", "THISDIAL=SIP/700") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [zap2dahdi@macro-dial-one:11] Return("SIP/31507580-000000e6", "") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:9] GotoIf("SIP/31507580-000000e6", "1?docheck") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (macro-dial-one,dstring,14)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:14] GotoIf("SIP/31507580-000000e6", "0?skipset") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:15] Set("SIP/31507580-000000e6", "DSTRING=SIP/700&") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:16] Set("SIP/31507580-000000e6", "ITER=2") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:17] GotoIf("SIP/31507580-000000e6", "0?begin") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:18] ExecIf("SIP/31507580-000000e6", "0?Return()") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:19] Set("SIP/31507580-000000e6", "DSTRING=SIP/700") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [dstring@macro-dial-one:20] Return("SIP/31507580-000000e6", "") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:28] GotoIf("SIP/31507580-000000e6", "0?nodial") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:29] GotoIf("SIP/31507580-000000e6", "0?skiptrace") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:30] GosubIf("SIP/31507580-000000e6", "1?ctset,1():ctclear,1()") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [ctset@macro-dial-one:1] Set("SIP/31507580-000000e6", "DB(CALLTRACE/700)=83860122") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [ctset@macro-dial-one:2] Return("SIP/31507580-000000e6", "") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:31] Set("SIP/31507580-000000e6", "D_OPTIONS=Ttr") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:32] NoOp("SIP/31507580-000000e6", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:33] ExecIf("SIP/31507580-000000e6", "0?Set(ALERT_INFO=)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:34] ExecIf("SIP/31507580-000000e6", "0?Set(ALERT_INFO=)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:35] ExecIf("SIP/31507580-000000e6", "0?Set(ALERT_INFO=)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:36] ExecIf("SIP/31507580-000000e6", "0?Set(ALERT_INFO=;volume=)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:37] ExecIf("SIP/31507580-000000e6", "0?Set(ALERT_INFO=;volume=)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:38] GosubIf("SIP/31507580-000000e6", "0?func-set-sipheader,s,1(Alert-Info,)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:39] ExecIf("SIP/31507580-000000e6", "0?Set(CHANNEL(musicclass)=)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:40] GosubIf("SIP/31507580-000000e6", "0?qwait,1()") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:41] Set("SIP/31507580-000000e6", "__CWIGNORE=") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:42] Set("SIP/31507580-000000e6", "__KEEPCID=TRUE") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:43] GotoIf("SIP/31507580-000000e6", "0?usegoto,1") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:44] GotoIf("SIP/31507580-000000e6", "1?godial") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx_builtins.c: Goto (macro-dial-one,s,49)
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:49] Macro("SIP/31507580-000000e6", "dialout-one-predial-hook,") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dialout-one-predial-hook:1] MacroExit("SIP/31507580-000000e6", "") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:50] ExecIf("SIP/31507580-000000e6", "0?Set(D_OPTIONS=trI)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] pbx.c: Executing [s@macro-dial-one:51] Dial("SIP/31507580-000000e6", "SIP/700,15,Ttrb(func-apply-sipheaders^s^1)") in new stack
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 10:26:29] VERBOSE[5677][C-00000056] netsock2.c: Using SIP RTP CoS mark 5

luongjames · April 9, 2017, 2:38am

FWIW: I just removed extension 800 and it’s the same.

[2017-04-09 10:35:03] VERBOSE[1889][C-00000058] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 10:35:03] VERBOSE[1889][C-00000058] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@from-trunk:1] NoOp("SIP/31507580-000000ea", "Catch-All DID Match - Found 600 - You probably want a DID for this.") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@from-trunk:2] Log("SIP/31507580-000000ea", "WARNING,Friendly Scanner from 203.117.31.248;branch=z9hG4bK6cbc.db426cd2.0") in new stack
[2017-04-09 10:35:03] WARNING[6660][C-00000058] Ext. 600: Friendly Scanner from 203.117.31.248;branch=z9hG4bK6cbc.db426cd2.0
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@from-trunk:3] Set("SIP/31507580-000000ea", "__FROM_DID=600") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@from-trunk:4] Goto("SIP/31507580-000000ea", "ext-did,s,1") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (ext-did,s,1)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:1] Set("SIP/31507580-000000ea", "__DIRECTION=INBOUND") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:2] Gosub("SIP/31507580-000000ea", "sub-record-check,s,1(in,s,dontcare)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/31507580-000000ea", "0?initialized") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:2] Set("SIP/31507580-000000ea", "__REC_STATUS=INITIALIZED") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:3] Set("SIP/31507580-000000ea", "NOW=1491705303") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:4] Set("SIP/31507580-000000ea", "__DAY=09") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:5] Set("SIP/31507580-000000ea", "__MONTH=04") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:6] Set("SIP/31507580-000000ea", "__YEAR=2017") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:7] Set("SIP/31507580-000000ea", "__TIMESTR=20170409-103503") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:8] Set("SIP/31507580-000000ea", "__FROMEXTEN=unknown") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:9] Set("SIP/31507580-000000ea", "__MON_FMT=wav") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/31507580-000000ea", "Recordings initialized") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/31507580-000000ea", "0?Set(ARG3=dontcare)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:12] Set("SIP/31507580-000000ea", "REC_POLICY_MODE_SAVE=") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/31507580-000000ea", "0?Set(REC_STATUS=NO)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/31507580-000000ea", "2?checkaction") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/31507580-000000ea", "1?sub-record-check,in,1") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (sub-record-check,in,1)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/31507580-000000ea", "Inbound Recording Check to s") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [in@sub-record-check:2] Set("SIP/31507580-000000ea", "FROMEXTEN=unknown") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/31507580-000000ea", "8?Set(FROMEXTEN=84011191)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/31507580-000000ea", "recordcheck,1(dontcare,in,s)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/31507580-000000ea", "Starting recording check against dontcare") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/31507580-000000ea", "dontcare") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/31507580-000000ea", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [in@sub-record-check:5] Return("SIP/31507580-000000ea", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:3] Gosub("SIP/31507580-000000ea", "app-blacklist-check,s,1()") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/31507580-000000ea", "0?blacklisted") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/31507580-000000ea", "CALLED_BLACKLIST=1") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/31507580-000000ea", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:4] ExecIf("SIP/31507580-000000ea", "0?Set(__FROM_DID=s)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:5] Set("SIP/31507580-000000ea", "CDR(did)=600") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:6] ExecIf("SIP/31507580-000000ea", "0 ?Set(CALLERID(name)=84011191)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:7] Set("SIP/31507580-000000ea", "__MOHCLASS=") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:8] Set("SIP/31507580-000000ea", "__REVERSAL_REJECT=FALSE") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:9] GotoIf("SIP/31507580-000000ea", "1?post-reverse-charge") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (ext-did,s,11)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:11] NoOp("SIP/31507580-000000ea", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:12] Set("SIP/31507580-000000ea", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:13] Set("SIP/31507580-000000ea", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:14] Set("SIP/31507580-000000ea", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:15] Set("SIP/31507580-000000ea", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:16] NoOp("SIP/31507580-000000ea", "CallerID Entry Point") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@ext-did:17] Goto("SIP/31507580-000000ea", "ext-group,600,1") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (ext-group,600,1)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:1] GotoIf("SIP/31507580-000000ea", "0?cid") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:2] PlayTones("SIP/31507580-000000ea", "ring") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:3] Progress("SIP/31507580-000000ea", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:4] Macro("SIP/31507580-000000ea", "user-callerid,") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:1] Set("SIP/31507580-000000ea", "TOUCH_MONITOR=1491705303.234") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:2] Set("SIP/31507580-000000ea", "AMPUSER=84011191") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:3] GotoIf("SIP/31507580-000000ea", "0?report") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:4] ExecIf("SIP/31507580-000000ea", "1?Set(REALCALLERIDNUM=84011191)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:5] Set("SIP/31507580-000000ea", "AMPUSER=") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:6] GotoIf("SIP/31507580-000000ea", "0?limit") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:7] Set("SIP/31507580-000000ea", "AMPUSERCIDNAME=") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:8] GotoIf("SIP/31507580-000000ea", "1?report") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (macro-user-callerid,s,15)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:15] GotoIf("SIP/31507580-000000ea", "0?continue") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:16] ExecIf("SIP/31507580-000000ea", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:17] Set("SIP/31507580-000000ea", "__TTL=64") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:18] GotoIf("SIP/31507580-000000ea", "1?continue") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (macro-user-callerid,s,29)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:29] Set("SIP/31507580-000000ea", "CALLERID(number)=84011191") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:30] Set("SIP/31507580-000000ea", "CALLERID(name)=84011191") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:31] GotoIf("SIP/31507580-000000ea", "0?cnum") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:32] Set("SIP/31507580-000000ea", "CDR(cnam)=84011191") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:33] Set("SIP/31507580-000000ea", "CDR(cnum)=84011191") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-user-callerid:34] Set("SIP/31507580-000000ea", "CHANNEL(language)=en") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:5] Macro("SIP/31507580-000000ea", "blkvm-setifempty,") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-blkvm-setifempty:1] GotoIf("SIP/31507580-000000ea", "1?init") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (macro-blkvm-setifempty,s,4)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-blkvm-setifempty:4] Set("SIP/31507580-000000ea", "__BLKVM_CHANNEL=SIP/31507580-000000ea") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-blkvm-setifempty:5] Set("SIP/31507580-000000ea", "SHARED(BLKVM,SIP/31507580-000000ea)=TRUE") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-blkvm-setifempty:6] Set("SIP/31507580-000000ea", "GOSUB_RETVAL=TRUE") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-blkvm-setifempty:7] MacroExit("SIP/31507580-000000ea", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:6] GotoIf("SIP/31507580-000000ea", "1?skipov") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (ext-group,600,9)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:9] Set("SIP/31507580-000000ea", "RRNODEST=") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:10] Set("SIP/31507580-000000ea", "__NODEST=600") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:11] GosubIf("SIP/31507580-000000ea", "0?sub-rgsetcid,s,1()") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:12] Gosub("SIP/31507580-000000ea", "sub-record-check,s,1(rg,600,dontcare)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/31507580-000000ea", "8?initialized") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (sub-record-check,s,10)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/31507580-000000ea", "Recordings initialized") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/31507580-000000ea", "0?Set(ARG3=dontcare)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:12] Set("SIP/31507580-000000ea", "REC_POLICY_MODE_SAVE=") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/31507580-000000ea", "0?Set(REC_STATUS=NO)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/31507580-000000ea", "2?checkaction") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/31507580-000000ea", "0?sub-record-check,rg,1") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:18] NoOp("SIP/31507580-000000ea", "Generic rg Recording Check - 84011191 600") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:19] Gosub("SIP/31507580-000000ea", "recordcheck,1(dontcare,rg,600)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/31507580-000000ea", "Starting recording check against dontcare") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/31507580-000000ea", "dontcare") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/31507580-000000ea", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@sub-record-check:20] Return("SIP/31507580-000000ea", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:13] Set("SIP/31507580-000000ea", "RingGroupMethod=ringall") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [600@ext-group:14] Macro("SIP/31507580-000000ea", "dial,20,Ttr,800-805-802-801") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:1] NoOp("SIP/31507580-000000ea", "Blind Transfer: , Attended Transfer: , User: , Alert Info: ") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:2] ExecIf("SIP/31507580-000000ea", "0?Set(ALERT_INFO=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:3] ExecIf("SIP/31507580-000000ea", "0?Set(ALERT_INFO=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:4] ExecIf("SIP/31507580-000000ea", "0?Set(ALERT_INFO=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:5] ExecIf("SIP/31507580-000000ea", "0?Set(CHANNEL(musicclass)=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:6] AGI("SIP/31507580-000000ea", "dialparties.agi") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Starting New Dialparties.agi
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Caller ID name is '84011191' number is '84011191'
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: CW Ignore is:
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: CF Ignore is:
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: CW IN_USE/BUSY is: 1
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Methodology of ring is 'ringall'
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Added extension 800 to extension map
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Added extension 805 to extension map
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Added extension 802 to extension map
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Added extension 801 to extension map
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Extension 800 cf is disabled
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Extension 805 cf is disabled
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Extension 802 cf is disabled
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Extension 801 cf is disabled
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Extension 800 do not disturb is disabled
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Extension 805 do not disturb is disabled
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Extension 802 do not disturb is disabled
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Extension 801 do not disturb is disabled
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: dbset CALLTRACE/800 to 84011191
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: dbset CALLTRACE/805 to 84011191
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: dbset CALLTRACE/802 to 84011191
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: dbset CALLTRACE/801 to 84011191
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: dialparties.agi: Filtered ARG3: 800-805-802-801
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] res_agi.c: <SIP/31507580-000000ea>AGI Script dialparties.agi completed, returning 0
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:9] NoOp("SIP/31507580-000000ea", "Returned from dialparties with groups to dial") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:10] Set("SIP/31507580-000000ea", "LOOPCNT=4") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:11] Set("SIP/31507580-000000ea", "ITER=1") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:12] Set("SIP/31507580-000000ea", "EXTTOCALL=800") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/31507580-000000ea", "Working with 800") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/31507580-000000ea", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/31507580-000000ea", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:16] Set("SIP/31507580-000000ea", "ITER=2") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/31507580-000000ea", "1?ndloopbegin") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:12] Set("SIP/31507580-000000ea", "EXTTOCALL=805") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/31507580-000000ea", "Working with 805") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/31507580-000000ea", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/31507580-000000ea", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:16] Set("SIP/31507580-000000ea", "ITER=3") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/31507580-000000ea", "1?ndloopbegin") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:12] Set("SIP/31507580-000000ea", "EXTTOCALL=802") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/31507580-000000ea", "Working with 802") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/31507580-000000ea", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/31507580-000000ea", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:16] Set("SIP/31507580-000000ea", "ITER=4") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/31507580-000000ea", "1?ndloopbegin") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx_builtins.c: Goto (macro-dial,s,12)
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:12] Set("SIP/31507580-000000ea", "EXTTOCALL=801") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:13] NoOp("SIP/31507580-000000ea", "Working with 801") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:14] ExecIf("SIP/31507580-000000ea", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:15] ExecIf("SIP/31507580-000000ea", "0?Set(HASH(__SIPHEADERS,Alert-Info)=;volume=)") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:16] Set("SIP/31507580-000000ea", "ITER=5") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:17] GotoIf("SIP/31507580-000000ea", "0?ndloopbegin") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:18] Macro("SIP/31507580-000000ea", "dial-ringall-predial-hook,") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial-ringall-predial-hook:1] MacroExit("SIP/31507580-000000ea", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@macro-dial:19] Dial("SIP/31507580-000000ea", "SIP/800&SIP/805&SIP/802&SIP/801,20,trM(auto-blkvm)b(func-apply-sipheaders^s^1),") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] netsock2.c: Using SIP RTP TOS bits 184
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] netsock2.c: Using SIP RTP CoS mark 5
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: SIP/800-000000eb Internal Gosub(func-apply-sipheaders,s,1) start
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/800-000000eb", "Applying SIP Headers to channel") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/800-000000eb", "SIPHEADERKEYS=") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/800-000000eb", "0") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_while.c: Jumping to priority 7
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/800-000000eb", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/800-000000eb'
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: SIP/800-000000eb Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: SIP/805-000000ec Internal Gosub(func-apply-sipheaders,s,1) start
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/805-000000ec", "Applying SIP Headers to channel") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/805-000000ec", "SIPHEADERKEYS=") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/805-000000ec", "0") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_while.c: Jumping to priority 7
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/805-000000ec", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/805-000000ec'
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: SIP/805-000000ec Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: SIP/802-000000ed Internal Gosub(func-apply-sipheaders,s,1) start
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/802-000000ed", "Applying SIP Headers to channel") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/802-000000ed", "SIPHEADERKEYS=") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/802-000000ed", "0") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_while.c: Jumping to priority 7
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/802-000000ed", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/802-000000ed'
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: SIP/802-000000ed Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: SIP/801-000000ee Internal Gosub(func-apply-sipheaders,s,1) start
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:1] NoOp("SIP/801-000000ee", "Applying SIP Headers to channel") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:2] Set("SIP/801-000000ee", "SIPHEADERKEYS=") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:3] While("SIP/801-000000ee", "0") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_while.c: Jumping to priority 7
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] pbx.c: Executing [s@func-apply-sipheaders:8] Return("SIP/801-000000ee", "") in new stack
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: Spawn extension (from-internal, 600, 1) exited non-zero on 'SIP/801-000000ee'
[2017-04-09 10:35:03] VERBOSE[6660][C-00000058] app_stack.c: SIP/801-000000ee Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=

astbox · April 10, 2017, 7:53am

Do you have two sip trunks (different numbers) with the same provider?

luongjames · April 10, 2017, 11:35am

Yes. I do have two sip trunks with the same provider.

One is hooked up to the ring group. The other is not.

Both were functioning before.

astbox · April 10, 2017, 11:54am

Put this in your sip options and try again

match_auth_username=yes