All Circuits Busy on Intra-Company Route (IAX2)

choiceit · March 13, 2018, 5:43pm

Hello guys, I have two freepbx systems. (13x and 14x) and I have setup IAX2 trunks and Outbound routes on both servers in order to have intercompany communication.

I have followed two separate tutorials, and I am getting ‘All Circuits are Busy’ when I try to dial the appropriate pattern to get the other office.

How can I troubleshoot this? I have confirmed the IAX2 connection using IAX2 show peers.

The two servers are communicating over a VPN. I’m not sure how the VPN is configured, but I can ping from both servers to each other.

I know this is not enough information, but I don’t know what info will be useful. Thanks

ahtel03*CLI> iax2 show peers
Name/Username Host Mask Port Status Description
InterOfficeToAB X.X.X.X (S) 255.255.255.255 4569 (T) OK (38 ms)
1 iax2 peers [1 online, 0 offline, 0 unmonitored]

(Tutorial I used) http://www.telecomworld101.com/Asterisk/TestingIAX2Trunks.html

choiceit · March 13, 2018, 5:51pm

Here is what a call trace shows:

choiceit · March 13, 2018, 5:52pm

cynjut · March 13, 2018, 6:05pm

Logs would be better for this.

choiceit · March 13, 2018, 6:08pm

=========================================================================
Connected to Asterisk 13.17.2 currently running on ahtel03 (pid = 2227)
== Spawn extension (macro-dial, s, 1) exited non-zero on ‘SIP/241-00006f60’
== Spawn extension (macro-dial, s, 22) exited non-zero on ‘SIP/cbeyond-in-00006f59’ in macro ‘dial’
== Extension Changed 241[ext-local] new state Idle for Notify User 202
== Spawn extension (ext-group, 601, 18) exited non-zero on ‘SIP/cbeyond-in-00006f59’
== Extension Changed 241[ext-local] new state Idle for Notify User 203
== Spawn extension (macro-hangupcall, s, 6) exited non-zero on ‘SIP/cbeyond-in-00006f59’ in macro ‘hangupcall’
== Spawn extension (ext-group, h, 1) exited non-zero on ‘SIP/cbeyond-in-00006f59’
== Spawn extension (ext-group, h, 1) exited non-zero on ‘SIP/cbeyond-in-00006f59’

<— SIP read from UDP:10.25.1.120:5060 —>
INVITE sip:[email protected]:5160;user=phone SIP/2.0
Via: SIP/2.0/UDP 10.25.1.120;branch=z9hG4bKc27c95e4D4EE0657
From: “Aaron” sip:[email protected];tag=310495F6-6D2D5E63
To: sip:[email protected];user=phone
CSeq: 1 INVITE
Call-ID: [email protected]
Contact: sip:[email protected]
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_601-UA/3.1.8.0070
Accept-Language: en
Supported: 100rel,replaces
Allow-Events: talk,hold,conference
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 268

v=0
o=- 1520964280 1520964280 IN IP4 10.25.1.120
s=Polycom IP Phone
c=IN IP4 10.25.1.120
t=0 0
a=sendrecv
m=audio 2236 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
<------------->
— (15 headers 12 lines) —
Sending to 10.25.1.120:5060 (NAT)
Sending to 10.25.1.120:5060 (NAT)
Using INVITE request as basis request - [email protected]
Found peer ‘201’ for ‘201’ from 10.25.1.120:5060

<— Reliably Transmitting (no NAT) to 10.25.1.120:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 10.25.1.120;branch=z9hG4bKc27c95e4D4EE0657;received=10.25.1.120
From: “Aaron” sip:[email protected];tag=310495F6-6D2D5E63
To: sip:[email protected];user=phone;tag=as1b07d28a
Call-ID: [email protected]
CSeq: 1 INVITE
Server: FPBX-14.0.1.36(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="4f8ebc31"
Content-Length: 0

<------------>
Scheduling destruction of SIP dialog ‘[email protected]’ in 6400 ms (Method: INVITE)

<— SIP read from UDP:10.25.1.120:5060 —>
ACK sip:[email protected]:5160 SIP/2.0
Via: SIP/2.0/UDP 10.25.1.120;branch=z9hG4bKc27c95e4D4EE0657
From: “Aaron” sip:[email protected];tag=310495F6-6D2D5E63
To: sip:[email protected];user=phone;tag=as1b07d28a
CSeq: 1 ACK
Call-ID: [email protected]
Contact: sip:[email protected]
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_601-UA/3.1.8.0070
Accept-Language: en
Max-Forwards: 70
Content-Length: 0

<------------->
— (12 headers 0 lines) —

<— SIP read from UDP:10.25.1.120:5060 —>
INVITE sip:[email protected]:5160;user=phone SIP/2.0
Via: SIP/2.0/UDP 10.25.1.120;branch=z9hG4bK770be6298BA1DAFC
From: “Aaron” sip:[email protected];tag=310495F6-6D2D5E63
To: sip:[email protected];user=phone
CSeq: 2 INVITE
Call-ID: [email protected]
Contact: sip:[email protected]
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_601-UA/3.1.8.0070
Accept-Language: en
Supported: 100rel,replaces
Allow-Events: talk,hold,conference
Authorization: Digest username=“201”, realm=“asterisk”, nonce=“4f8ebc31”, uri=“sip:[email protected]:5160;user=phone”, response=“96925ed13b3cfa04ddcb8d302263243b”, algorithm=MD5
Max-Forwards: 70
Content-Type: application/sdp
Content-Length: 268

v=0
o=- 1520964280 1520964280 IN IP4 10.25.1.120
s=Polycom IP Phone
c=IN IP4 10.25.1.120
t=0 0
a=sendrecv
m=audio 2236 RTP/AVP 0 8 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
<------------->
— (16 headers 12 lines) —
Sending to 10.25.1.120:5060 (no NAT)
Using INVITE request as basis request - [email protected]
Found peer ‘201’ for ‘201’ from 10.25.1.120:5060
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
Found RTP audio format 0
Found RTP audio format 8
Found RTP audio format 18
Found RTP audio format 101
Found audio description format PCMU for ID 0
Found audio description format PCMA for ID 8
Found audio description format G729 for ID 18
Found audio description format telephone-event for ID 101
Capabilities: us - (ulaw|alaw|gsm|g726|g722), peer - audio=(ulaw|alaw|g729)/video=(nothing)/text=(nothing), combined - (ulaw|alaw)
Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|)
Peer audio RTP is at port 10.25.1.120:2236
Looking for 3301 in from-internal (domain 10.25.1.5)
sip_route_dump: route/path hop: sip:[email protected]

<— Transmitting (no NAT) to 10.25.1.120:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.25.1.120;branch=z9hG4bK770be6298BA1DAFC;received=10.25.1.120
From: “Aaron” sip:[email protected];tag=310495F6-6D2D5E63
To: sip:[email protected];user=phone
Call-ID: [email protected]
CSeq: 2 INVITE
Server: FPBX-14.0.1.36(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: sip:[email protected]:5160
Content-Length: 0

<------------>
== Spawn extension (, 3301, 1) exited non-zero on ‘IAX2/InterOfficeToAB-peer-23791’

<— Transmitting (no NAT) to 10.25.1.120:5060 —>
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.25.1.120;branch=z9hG4bK770be6298BA1DAFC;received=10.25.1.120
From: “Aaron” sip:[email protected];tag=310495F6-6D2D5E63
To: sip:[email protected];user=phone;tag=as3181c551
Call-ID: [email protected]
CSeq: 2 INVITE
Server: FPBX-14.0.1.36(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Contact: sip:[email protected]:5160
Content-Length: 0

<------------>
== Everyone is busy/congested at this time (1:0/0/1)
Audio is at 19722
Adding codec ulaw to SDP
Adding codec alaw to SDP
Adding non-codec 0x1 (telephone-event) to SDP

<— Transmitting (no NAT) to 10.25.1.120:5060 —>
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 10.25.1.120;branch=z9hG4bK770be6298BA1DAFC;received=10.25.1.120
From: “Aaron” sip:[email protected];tag=310495F6-6D2D5E63
To: sip:[email protected];user=phone;tag=as3181c551
Call-ID: [email protected]
CSeq: 2 INVITE
Server: FPBX-14.0.1.36(13.17.2)
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: 268

v=0
o=root 620326808 620326808 IN IP4 10.25.1.5
s=Asterisk PBX 13.17.2
c=IN IP4 10.25.1.5
t=0 0
m=audio 19722 RTP/AVP 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

<------------>

<— Reliably Transmitting (no NAT) to 10.25.1.120:5060 —>
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/UDP 10.25.1.120;branch=z9hG4bK770be6298BA1DAFC;received=10.25.1.120
From: “Aaron” sip:[email protected];tag=310495F6-6D2D5E63
To: sip:[email protected];user=phone;tag=as3181c551
Call-ID: [email protected]
CSeq: 2 INVITE
Server: FPBX-14.0.1.36(13.17.2)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
X-Asterisk-HangupCause: Facility not subscribed
X-Asterisk-HangupCauseCode: 50
Content-Length: 0

<------------>
[2018-03-13 12:08:04] WARNING[16694][C-000016d7]: channel.c:5005 ast_prod: Prodding channel ‘SIP/201-00006f6c’ failed
== Spawn extension (macro-outisbusy, intracompany, 2) exited non-zero on ‘SIP/201-00006f6c’ in macro ‘outisbusy’
== Spawn extension (from-internal, 3301, 9) exited non-zero on ‘SIP/201-00006f6c’

<— SIP read from UDP:10.25.1.120:5060 —>
ACK sip:[email protected]:5160 SIP/2.0
Via: SIP/2.0/UDP 10.25.1.120;branch=z9hG4bK770be6298BA1DAFC
From: “Aaron” sip:[email protected];tag=310495F6-6D2D5E63
To: sip:[email protected];user=phone;tag=as3181c551
CSeq: 2 ACK
Call-ID: [email protected]
Contact: sip:[email protected]
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, INFO, MESSAGE, SUBSCRIBE, NOTIFY, PRACK, UPDATE, REFER
User-Agent: PolycomSoundPointIP-SPIP_601-UA/3.1.8.0070
Accept-Language: en
Max-Forwards: 70
Content-Length: 0

<------------->
— (12 headers 0 lines) —
== Spawn extension (macro-hangupcall, s, 6) exited non-zero on ‘SIP/201-00006f6c’ in macro ‘hangupcall’
== Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/201-00006f6c’
== Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/201-00006f6c’
Really destroying SIP dialog ‘[email protected]’ Method: ACK

choiceit · March 13, 2018, 6:10pm

The dial pattern is set to Prefix 3, then 3XX.

I am dialing 3301 (301 is an extension on the destination server)

choiceit · March 13, 2018, 6:11pm

The local IP of the source server is 10.25.1.5. The local IP of the destination server is 10.0.1.69.

I can ping between the two servers through the VPN.

choiceit · March 13, 2018, 6:15pm

Ok, It just occured to me. Why is SIP debug giving me output if the trunk is IAX2?

Here is output of IAX2 debug.

ahtel03*CLI> iax2 set debug on
IAX2 Debugging Enabled
Tx-Frame Retry[000] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW
Timestamp: 00008ms SCall: 26858 DCall: 00000 10.0.1.69:4569
VERSION : 2
CALLED NUMBER : 301
CODEC_PREFS : (ulaw|alaw|gsm)
CALLING NUMBER : 201
CALLING PRESNTN : 0
CALLING TYPEOFN : 0
CALLING TRANSIT : 0
CALLING NAME : Aaron
LANGUAGE : en
USERNAME : InterOfficeToAB-user
FORMAT : 4
FORMAT2 : ulaw
CAPABILITY : 14
CAPABILITY2 : Unknown
ADSICPE : 2
DATE TIME : 2018-03-13 12:15:08

Rx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN
Timestamp: 00008ms SCall: 00001 DCall: 26858 10.0.1.69:4569
CALLTOKEN : 51 bytes

Tx-Frame Retry[000] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW
Timestamp: 00046ms SCall: 26858 DCall: 00000 10.0.1.69:4569
VERSION : 2
CALLED NUMBER : 301
CODEC_PREFS : (ulaw|alaw|gsm)
CALLING NUMBER : 201
CALLING PRESNTN : 0
CALLING TYPEOFN : 0
CALLING TRANSIT : 0
CALLING NAME : Aaron
LANGUAGE : en
USERNAME : InterOfficeToAB-user
FORMAT : 4
FORMAT2 : ulaw
CAPABILITY : 14
CAPABILITY2 : Unknown
ADSICPE : 2
DATE TIME : 2018-03-13 12:15:08
CALLTOKEN : 51 bytes

Rx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: AUTHREQ
Timestamp: 00007ms SCall: 08959 DCall: 26858 10.0.1.69:4569
AUTHMETHODS : 3
CHALLENGE : \x32\x30\x34\x32\x37\x30\x34\x30\x37
USERNAME : InterOfficeToAB-user

Tx-Frame Retry[000] – OSeqno: 001 ISeqno: 001 Type: IAX Subclass: AUTHREP
Timestamp: 00084ms SCall: 26858 DCall: 08959 10.0.1.69:4569
MD5 RESULT : eb59f58e793ff2366a0336c9a64961fa

Rx-Frame Retry[ No] – OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACK
Timestamp: 00084ms SCall: 08959 DCall: 26858 10.0.1.69:4569
Rx-Frame Retry[ No] – OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REJECT
Timestamp: 00044ms SCall: 08959 DCall: 26858 10.0.1.69:4569
CAUSE : No authority found
CAUSE CODE : 50

Tx-Frame Retry[-01] – OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK
Timestamp: 00044ms SCall: 26858 DCall: 08959 10.0.1.69:4569

cynjut · March 13, 2018, 6:16pm

Thank god you left the SIP DEBUG turned on - no one wants this to be easy!

choiceit · March 13, 2018, 6:16pm

Sorry, I realized that SIP debugging wasn’t what I should be looking at (duh). I posted the result of IAX2 debug output above.

Sorry!

From what I can tell, the issue is that the server is not subscribing properly?

cynjut · March 13, 2018, 6:20pm

You are calling 201 from 241, right?

You aren’t using your IAX2 trunk, if I can sift through all the extra crap to get to the call setup. It looks like you’re trying to connect via SIP.

choiceit · March 13, 2018, 6:21pm

I am calling from extension 201 at office A. I am dialing ‘3301’ to reach 301 at office B.

The dial pattern on my outbound route has prefix 3 and then 3XX.

I posted the IAX2 debug output above, and it appears to be using IAX2 when I dial 3301.

cynjut · March 13, 2018, 6:23pm

Turn off the debug. I’m guessing that the IAX2 setup is horked, and the straight logs will tell us everything we need to know - specifically, that you are probably using passwords for what should probably be an IP-based authentication connection.

At this point in the process, we’re still trying to find the field. You’re already cutting the grass with tweezers.

choiceit · March 13, 2018, 6:25pm

Output of /var/log/asterisk/full around the time of the failed call. SIP and IAX2 debug turned off.

[2018-03-13 12:22:28] VERBOSE[7630] chan_iax2.c: Tx-Frame Retry[000] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE
[2018-03-13 12:22:28] VERBOSE[7630] chan_iax2.c: Timestamp: 00013ms SCall: 04126 DCall: 00000 10.0.1.69:4569
[2018-03-13 12:22:28] VERBOSE[7630] chan_iax2.c:
[2018-03-13 12:22:28] VERBOSE[7639] chan_iax2.c: Rx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG
[2018-03-13 12:22:28] VERBOSE[7639] chan_iax2.c: Timestamp: 00013ms SCall: 00001 DCall: 04126 10.0.1.69:4569
[2018-03-13 12:22:28] VERBOSE[7639] chan_iax2.c: Tx-Frame Retry[-01] – OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK
[2018-03-13 12:22:28] VERBOSE[7639] chan_iax2.c: Timestamp: 00013ms SCall: 04126 DCall: 00001 10.0.1.69:4569
[2018-03-13 12:22:37] VERBOSE[7638] chan_iax2.c: Rx-Frame Retry[ No] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE
[2018-03-13 12:22:37] VERBOSE[7638] chan_iax2.c: Timestamp: 00010ms SCall: 06594 DCall: 00000 10.0.1.69:4569
[2018-03-13 12:22:37] VERBOSE[7638] chan_iax2.c:
[2018-03-13 12:22:37] VERBOSE[7638] chan_iax2.c: Tx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG
[2018-03-13 12:22:37] VERBOSE[7638] chan_iax2.c: Timestamp: 00010ms SCall: 00001 DCall: 06594 10.0.1.69:4569
[2018-03-13 12:22:37] VERBOSE[7641] chan_iax2.c: Rx-Frame Retry[ No] – OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK
[2018-03-13 12:22:37] VERBOSE[7641] chan_iax2.c: Timestamp: 00010ms SCall: 06594 DCall: 00001 10.0.1.69:4569
[2018-03-13 12:23:28] VERBOSE[7630] chan_iax2.c: Tx-Frame Retry[000] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE
[2018-03-13 12:23:28] VERBOSE[7630] chan_iax2.c: Timestamp: 00019ms SCall: 14203 DCall: 00000 10.0.1.69:4569
[2018-03-13 12:23:28] VERBOSE[7630] chan_iax2.c:
[2018-03-13 12:23:28] VERBOSE[7642] chan_iax2.c: Rx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG
[2018-03-13 12:23:28] VERBOSE[7642] chan_iax2.c: Timestamp: 00019ms SCall: 00001 DCall: 14203 10.0.1.69:4569
[2018-03-13 12:23:28] VERBOSE[7642] chan_iax2.c: Tx-Frame Retry[-01] – OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK
[2018-03-13 12:23:28] VERBOSE[7642] chan_iax2.c: Timestamp: 00019ms SCall: 14203 DCall: 00001 10.0.1.69:4569
[2018-03-13 12:23:33] VERBOSE[25429][C-000016e3] bridge_channel.c: Channel SIP/238-00006fc1 left ‘simple_bridge’ basic-bridge <43ccb0b2-6a06-4c7b-90aa-540fab52571d>
[2018-03-13 12:23:33] VERBOSE[25429][C-000016e3] app_macro.c: Spawn extension (macro-dialout-trunk, s, 31) exited non-zero on ‘SIP/238-00006fc1’ in macro ‘dialout-trunk’
[2018-03-13 12:23:33] VERBOSE[25429][C-000016e3] pbx.c: Spawn extension (from-internal, 418884237834, 7) exited non-zero on ‘SIP/238-00006fc1’
[2018-03-13 12:23:33] VERBOSE[25429][C-000016e3] pbx.c: Executing [h@from-internal:1] Macro(“SIP/238-00006fc1”, “hangupcall”) in new stack
[2018-03-13 12:23:33] VERBOSE[25490][C-000016e3] bridge_channel.c: Channel SIP/AAHTrunk-00006fc3 left ‘simple_bridge’ basic-bridge <43ccb0b2-6a06-4c7b-90aa-540fab52571d>
[2018-03-13 12:23:33] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@macro-hangupcall:1] GotoIf(“SIP/238-00006fc1”, “1?theend”) in new stack
[2018-03-13 12:23:33] VERBOSE[25429][C-000016e3] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-03-13 12:23:33] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@macro-hangupcall:3] ExecIf(“SIP/238-00006fc1”, “0?Set(CDR(recordingfile)=)”) in new stack
[2018-03-13 12:23:33] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@macro-hangupcall:4] NoOp(“SIP/238-00006fc1”, "SIP/AAHTrunk-00006fc3 monior file= ") in new stack
[2018-03-13 12:23:33] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@macro-hangupcall:5] AGI(“SIP/238-00006fc1”, “attendedtransfer-rec-restart.php,SIP/AAHTrunk-00006fc3,”) in new stack
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] res_agi.c: <SIP/238-00006fc1>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@macro-hangupcall:6] Hangup(“SIP/238-00006fc1”, “”) in new stack
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on ‘SIP/238-00006fc1’ in macro ‘hangupcall’
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/238-00006fc1’
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] app_stack.c: SIP/238-00006fc1 Internal Gosub(crm-hangup,s,1) start
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@crm-hangup:1] NoOp(“SIP/238-00006fc1”, “Sending Hangup to CRM”) in new stack
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@crm-hangup:2] NoOp(“SIP/238-00006fc1”, “HANGUP CAUSE: 16”) in new stack
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@crm-hangup:3] ExecIf(“SIP/238-00006fc1”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@crm-hangup:4] NoOp(“SIP/238-00006fc1”, “MASTER CHANNEL: 1520965340.41398 = 1520965340.41398”) in new stack
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@crm-hangup:5] GotoIf(“SIP/238-00006fc1”, “0?return”) in new stack
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@crm-hangup:6] Set(“SIP/238-00006fc1”, “__CRM_HANGUP=1”) in new stack
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@crm-hangup:7] AGI(“SIP/238-00006fc1”, “sangomacrm.agi”) in new stack
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] res_agi.c: <SIP/238-00006fc1>AGI Script sangomacrm.agi completed, returning 0
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] pbx.c: Executing [s@crm-hangup:8] Return(“SIP/238-00006fc1”, “”) in new stack
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] app_stack.c: Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/238-00006fc1’
[2018-03-13 12:23:34] VERBOSE[25429][C-000016e3] app_stack.c: SIP/238-00006fc1 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2018-03-13 12:23:34] VERBOSE[7580] chan_sip.c: Extension Changed 238[ext-local] new state Idle for Notify User 233
[2018-03-13 12:23:37] VERBOSE[7636] chan_iax2.c: Rx-Frame Retry[ No] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE
[2018-03-13 12:23:37] VERBOSE[7636] chan_iax2.c: Timestamp: 00007ms SCall: 03486 DCall: 00000 10.0.1.69:4569
[2018-03-13 12:23:37] VERBOSE[7636] chan_iax2.c:
[2018-03-13 12:23:37] VERBOSE[7636] chan_iax2.c: Tx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG
[2018-03-13 12:23:37] VERBOSE[7636] chan_iax2.c: Timestamp: 00007ms SCall: 00001 DCall: 03486 10.0.1.69:4569
[2018-03-13 12:23:37] VERBOSE[7634] chan_iax2.c: Rx-Frame Retry[ No] – OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK
[2018-03-13 12:23:37] VERBOSE[7634] chan_iax2.c: Timestamp: 00007ms SCall: 03486 DCall: 00001 10.0.1.69:4569
[2018-03-13 12:23:56] VERBOSE[7551] asterisk.c: Remote UNIX connection
[2018-03-13 12:24:07] VERBOSE[7628][C-000016e5] netsock2.c: Using SIP RTP TOS bits 184
[2018-03-13 12:24:07] VERBOSE[7628][C-000016e5] netsock2.c: Using SIP RTP CoS mark 5
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [3301@from-internal:1] Macro(“SIP/201-00006fc6”, “user-callerid,LIMIT,EXTERNAL,”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:1] Set(“SIP/201-00006fc6”, “TOUCH_MONITOR=1520965447.41403”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:2] Set(“SIP/201-00006fc6”, “AMPUSER=201”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:3] GotoIf(“SIP/201-00006fc6”, “0?report”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:4] ExecIf(“SIP/201-00006fc6”, “1?Set(REALCALLERIDNUM=201)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:5] Set(“SIP/201-00006fc6”, “AMPUSER=201”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:6] GotoIf(“SIP/201-00006fc6”, “0?limit”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:7] Set(“SIP/201-00006fc6”, “AMPUSERCIDNAME=Aaron”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:8] ExecIf(“SIP/201-00006fc6”, “0?Set(__CIDMASQUERADING=TRUE)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:9] GotoIf(“SIP/201-00006fc6”, “0?report”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:10] Set(“SIP/201-00006fc6”, “AMPUSERCID=201”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:11] Set(“SIP/201-00006fc6”, “__DIAL_OPTIONS=HhTtr”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:12] Set(“SIP/201-00006fc6”, “CALLERID(all)=“Aaron” <201>”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:13] GotoIf(“SIP/201-00006fc6”, “0?limit”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:14] ExecIf(“SIP/201-00006fc6”, “1?Set(GROUP(concurrency_limit)=201)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:15] ExecIf(“SIP/201-00006fc6”, “0?Set(CHANNEL(language)=)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:16] NoOp(“SIP/201-00006fc6”, “Macro Depth is 1”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:17] GotoIf(“SIP/201-00006fc6”, “1?report2:macroerror”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (macro-user-callerid,s,19)
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:19] GotoIf(“SIP/201-00006fc6”, “1?continue”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (macro-user-callerid,s,37)
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:37] Set(“SIP/201-00006fc6”, “CALLERID(number)=201”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:38] Set(“SIP/201-00006fc6”, “CALLERID(name)=Aaron”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:39] GotoIf(“SIP/201-00006fc6”, “0?cnum”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:40] Set(“SIP/201-00006fc6”, “CDR(cnam)=Aaron”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:41] Set(“SIP/201-00006fc6”, “CDR(cnum)=201”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-user-callerid:42] Set(“SIP/201-00006fc6”, “CHANNEL(language)=en”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [3301@from-internal:2] Gosub(“SIP/201-00006fc6”, “sub-record-check,s,1(out,3301,dontcare)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:1] GotoIf(“SIP/201-00006fc6”, “0?initialized”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:2] Set(“SIP/201-00006fc6”, “__REC_STATUS=INITIALIZED”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:3] Set(“SIP/201-00006fc6”, “NOW=1520965447”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:4] Set(“SIP/201-00006fc6”, “__DAY=13”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:5] Set(“SIP/201-00006fc6”, “__MONTH=03”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:6] Set(“SIP/201-00006fc6”, “__YEAR=2018”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:7] Set(“SIP/201-00006fc6”, “__TIMESTR=20180313-122407”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:8] Set(“SIP/201-00006fc6”, “__FROMEXTEN=201”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:9] Set(“SIP/201-00006fc6”, “__MON_FMT=wav”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:10] NoOp(“SIP/201-00006fc6”, “Recordings initialized”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:11] ExecIf(“SIP/201-00006fc6”, “0?Set(ARG3=dontcare)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:12] Set(“SIP/201-00006fc6”, “REC_POLICY_MODE_SAVE=”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:13] ExecIf(“SIP/201-00006fc6”, “0?Set(REC_STATUS=NO)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:14] GotoIf(“SIP/201-00006fc6”, “3?checkaction”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (sub-record-check,s,17)
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@sub-record-check:17] GotoIf(“SIP/201-00006fc6”, “1?sub-record-check,out,1”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (sub-record-check,out,1)
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [out@sub-record-check:1] NoOp(“SIP/201-00006fc6”, “Outbound Recording Check from 201 to 3301”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [out@sub-record-check:2] Set(“SIP/201-00006fc6”, “RECMODE=dontcare”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [out@sub-record-check:3] ExecIf(“SIP/201-00006fc6”, “1?Goto(routewins)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (sub-record-check,out,7)
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [out@sub-record-check:7] Gosub(“SIP/201-00006fc6”, “recordcheck,1(dontcare,out,3301)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“SIP/201-00006fc6”, “Starting recording check against dontcare”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“SIP/201-00006fc6”, “dontcare”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“SIP/201-00006fc6”, “”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [out@sub-record-check:8] Return(“SIP/201-00006fc6”, “”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [3301@from-internal:3] ExecIf(“SIP/201-00006fc6”, “0 ?Set(CDR(accountcode)=)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [3301@from-internal:4] Set(“SIP/201-00006fc6”, “INTRACOMPANYROUTE=YES”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [3301@from-internal:5] Set(“SIP/201-00006fc6”, “MOHCLASS=default”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [3301@from-internal:6] ExecIf(“SIP/201-00006fc6”, “1?Set(TRUNKCIDOVERRIDE=<7196341100>)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [3301@from-internal:7] Set(“SIP/201-00006fc6”, “_NODEST=”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [3301@from-internal:8] Macro(“SIP/201-00006fc6”, “dialout-trunk,1,301,off”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:1] Set(“SIP/201-00006fc6”, “DIAL_TRUNK=1”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:2] GosubIf(“SIP/201-00006fc6”, “0?sub-pincheck,s,1()”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:3] ExecIf(“SIP/201-00006fc6”, “0?Set(CALLERID(num)=201)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:4] GotoIf(“SIP/201-00006fc6”, “0?disabletrunk,1”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:5] Set(“SIP/201-00006fc6”, “DIAL_NUMBER=301”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:6] Set(“SIP/201-00006fc6”, “DIAL_TRUNK_OPTIONS=HhTtr”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:7] Set(“SIP/201-00006fc6”, “OUTBOUND_GROUP=OUT_1”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:8] Set(“SIP/201-00006fc6”, “DIAL_TRUNK_OPTIONS=Ttr”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:9] GotoIf(“SIP/201-00006fc6”, “1?nomax”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (macro-dialout-trunk,s,11)
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:11] GotoIf(“SIP/201-00006fc6”, “1?skipoutcid”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (macro-dialout-trunk,s,13)
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:13] GosubIf(“SIP/201-00006fc6”, “0?sub-flp-1,s,1()”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:14] Set(“SIP/201-00006fc6”, “OUTNUM=301”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:15] Set(“SIP/201-00006fc6”, “custom=IAX2/InterOfficeToAB-peer”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:16] ExecIf(“SIP/201-00006fc6”, “0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)Ttr)”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:17] ExecIf(“SIP/201-00006fc6”, “0?Set(DIAL_TRUNK_OPTIONS=TtrM(confirm))”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:18] Macro(“SIP/201-00006fc6”, “dialout-trunk-predial-hook,”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit(“SIP/201-00006fc6”, “”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:19] GotoIf(“SIP/201-00006fc6”, “0?skipcrm”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:20] Set(“SIP/201-00006fc6”, “__CRM_DIRECTION=OUTBOUND”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:21] Set(“SIP/201-00006fc6”, “__CRM_DESTINATION=301”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:22] Set(“SIP/201-00006fc6”, “__CRM_SOURCE=201”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:23] AGI(“SIP/201-00006fc6”, “sangomacrm.agi”) in new stack
[2018-03-13 12:24:07] VERBOSE[26489][C-000016e5] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] res_agi.c: <SIP/201-00006fc6>AGI Script sangomacrm.agi completed, returning 0
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:24] Set(“SIP/201-00006fc6”, “CHANNEL(hangup_handler_push)=crm-hangup,s,1”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:25] NoOp(“SIP/201-00006fc6”, “CRM Finished”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:26] GotoIf(“SIP/201-00006fc6”, “0?bypass,1”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:27] ExecIf(“SIP/201-00006fc6”, “1?Set(CONNECTEDLINE(num,i)=301)”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:28] ExecIf(“SIP/201-00006fc6”, “1?Set(CONNECTEDLINE(name,i)=CID:201)”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:29] ExecIf(“SIP/201-00006fc6”, “0?Set(CONNECTEDLINE(name,i)=CID:(Hidden)201)”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:30] GotoIf(“SIP/201-00006fc6”, “0?customtrunk”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:31] Dial(“SIP/201-00006fc6”, “IAX2/InterOfficeToAB-peer/301,300,Ttrb(func-apply-sipheaders^s^1)”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] app_stack.c: IAX2/InterOfficeToAB-peer-30228 Internal Gosub(func-apply-sipheaders,s,1) start
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@func-apply-sipheaders:1] ExecIf(“IAX2/InterOfficeToAB-peer-30228”, “0?Set(CHANNEL(hangup_handler_push)=crm-hangup,s,1)”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@func-apply-sipheaders:2] NoOp(“IAX2/InterOfficeToAB-peer-30228”, “Applying SIP Headers to channel”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@func-apply-sipheaders:3] Set(“IAX2/InterOfficeToAB-peer-30228”, “SIPHEADERKEYS=”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@func-apply-sipheaders:4] While(“IAX2/InterOfficeToAB-peer-30228”, “0”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] app_while.c: Jumping to priority 8
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@func-apply-sipheaders:9] Return(“IAX2/InterOfficeToAB-peer-30228”, “”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] app_stack.c: Spawn extension (, 3301, 1) exited non-zero on ‘IAX2/InterOfficeToAB-peer-30228’
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] app_stack.c: IAX2/InterOfficeToAB-peer-30228 Internal Gosub(func-apply-sipheaders,s,1) complete GOSUB_RETVAL=
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] app_dial.c: Called IAX2/InterOfficeToAB-peer/301
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] chan_iax2.c: Hungup ‘IAX2/InterOfficeToAB-peer-30228’
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:32] NoOp(“SIP/201-00006fc6”, “Dial failed for some reason with DIALSTATUS = CHANUNAVAIL and HANGUPCAUSE = 50”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-dialout-trunk:33] GotoIf(“SIP/201-00006fc6”, “0?continue,1:s-CHANUNAVAIL,1”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (macro-dialout-trunk,s-CHANUNAVAIL,1)
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:1] Set(“SIP/201-00006fc6”, “RC=50”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s-CHANUNAVAIL@macro-dialout-trunk:2] Goto(“SIP/201-00006fc6”, “50,1”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (macro-dialout-trunk,50,1)
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [50@macro-dialout-trunk:1] Goto(“SIP/201-00006fc6”, “continue,1”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (macro-dialout-trunk,continue,1)
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [continue@macro-dialout-trunk:1] NoOp(“SIP/201-00006fc6”, “TRUNK Dial failed due to CHANUNAVAIL HANGUPCAUSE: 50 - failing through to other trunks”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [continue@macro-dialout-trunk:2] ExecIf(“SIP/201-00006fc6”, “1?Set(CALLERID(number)=201)”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [3301@from-internal:9] Macro(“SIP/201-00006fc6”, “outisbusy,”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-outisbusy:1] Progress(“SIP/201-00006fc6”, “”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-outisbusy:2] GotoIf(“SIP/201-00006fc6”, “0?emergency,1”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-outisbusy:3] GotoIf(“SIP/201-00006fc6”, “1?intracompany,1”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (macro-outisbusy,intracompany,1)
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] pbx.c: Executing [intracompany@macro-outisbusy:1] Playback(“SIP/201-00006fc6”, “all-circuits-busy-now&please-try-call-later, noanswer”) in new stack
[2018-03-13 12:24:08] VERBOSE[26489][C-000016e5] file.c: <SIP/201-00006fc6> Playing ‘all-circuits-busy-now.ulaw’ (language ‘en’)
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] file.c: <SIP/201-00006fc6> Playing ‘please-try-call-later.ulaw’ (language ‘en’)
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [h@from-internal:1] Macro(“SIP/201-00006fc6”, “hangupcall”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-hangupcall:1] GotoIf(“SIP/201-00006fc6”, “1?theend”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-hangupcall:3] ExecIf(“SIP/201-00006fc6”, “0?Set(CDR(recordingfile)=)”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-hangupcall:4] NoOp(“SIP/201-00006fc6”, " monior file= ") in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-hangupcall:5] AGI(“SIP/201-00006fc6”, “attendedtransfer-rec-restart.php,”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/attendedtransfer-rec-restart.php
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] res_agi.c: <SIP/201-00006fc6>AGI Script attendedtransfer-rec-restart.php completed, returning 0
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@macro-hangupcall:6] Hangup(“SIP/201-00006fc6”, “”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] app_macro.c: Spawn extension (macro-hangupcall, s, 6) exited non-zero on ‘SIP/201-00006fc6’ in macro ‘hangupcall’
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/201-00006fc6’
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] app_stack.c: SIP/201-00006fc6 Internal Gosub(crm-hangup,s,1) start
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@crm-hangup:1] NoOp(“SIP/201-00006fc6”, “Sending Hangup to CRM”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@crm-hangup:2] NoOp(“SIP/201-00006fc6”, “HANGUP CAUSE: 50”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@crm-hangup:3] ExecIf(“SIP/201-00006fc6”, “0?Set(__CRM_VOICEMAIL=)”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@crm-hangup:4] NoOp(“SIP/201-00006fc6”, “MASTER CHANNEL: 1520965447.41403 = 1520965447.41403”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@crm-hangup:5] GotoIf(“SIP/201-00006fc6”, “0?return”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@crm-hangup:6] Set(“SIP/201-00006fc6”, “__CRM_HANGUP=1”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@crm-hangup:7] AGI(“SIP/201-00006fc6”, “sangomacrm.agi”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/sangomacrm.agi
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] res_agi.c: <SIP/201-00006fc6>AGI Script sangomacrm.agi completed, returning 0
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] pbx.c: Executing [s@crm-hangup:8] Return(“SIP/201-00006fc6”, “”) in new stack
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] app_stack.c: Spawn extension (from-internal, h, 1) exited non-zero on ‘SIP/201-00006fc6’
[2018-03-13 12:24:10] VERBOSE[26489][C-000016e5] app_stack.c: SIP/201-00006fc6 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=
[2018-03-13 12:24:12] VERBOSE[26331] asterisk.c: Remote UNIX connection disconnected

choiceit · March 13, 2018, 6:28pm

Sorry for the wall of log output. If you have a better way for me to get the info you want, please tell me!

cynjut · March 13, 2018, 6:36pm

OK. Here’s where the call fails. what do the logs on the other end say? Assuming the trunk is working, there could be a problem with the receiving context or the phone could actually be busy.

cynjut · March 13, 2018, 6:37pm

There’s a nagging thought in the back of my head about problems connecting Asterisk 13 and 14 with IAX2 trunks. Seems to me there was a similar thread a few months ago where the user ended up using a pair of PJ-SIP trunks using IP authentication…

choiceit · March 13, 2018, 6:47pm

I see no mention of IAX on the destination server’s logs. Perhaps I will try a pair of SIP trunks with IP authentication?

cynjut · March 13, 2018, 7:00pm

Try it and see. The fact that no IAX2 trunk action is happening tells me that the IAX2 from the 13 server to the 14 server isn’t registered, even though the connection the other way is working.

Remember - none of these are ‘bidirectional’. All of these trunks are really pairs of one-way connections, and even then they aren’t always.

avayax · March 14, 2018, 2:09am

Your are getting a cause code 50, no authority found error on your iax trunk.
I had a similar issue where a trunk of mine connecting two servers would suddenly show this error in one direction.
It was working before and I couldn’t recall I had made any changes.
I couldn’t find anybody, also on the Asterisk forum who knew anything about this error.

My solution was to drop iax and use sip, which worked