| Summary: | ASTERISK-23979: IAX2 trunk dial status and hangup cause not sent to SIP endpoint | ||||
| Reporter: | David Herselman (bbs2web) | Labels: | |||
| Date Opened: | 2014-07-01 16:53:46 | Date Closed: | 2014-07-09 15:52:14 | ||
| Priority: | Critical | Regression? | |||
| Status: | Closed/Complete | Components: | Channels/chan_sip/General | ||
| Versions: | 11.9.0 | Frequency of Occurrence | Constant | ||
| Related Issues: |
| ||||
| Environment: | IAX2 trunk with SIP end points | Attachments: | |||
| Description: | This is a long standing issue, with an existing bug report dating back to Asterisk 1.4, being reported in 2010 (ASTERISK-15925).
IAX2 trunk call termination status (DIALSTATUS and HANGUPCAUSE) received from upstream system is not translated to SIP end points. Calling a busy number results in SIP end point simply hanging up the call with normal clearing. {noformat} SIP provider ----- Asterisk A ===IAX2=== Asterisk B ----- SIP end point {noformat} SIP provider: ECN Asterisk A: IP of 192.25.69.236 Asterisk B: 0117211900 as IAX2 trunk SIP end point: 'David Herselman' extension 1904 on lair.co.za Busy destination: (+27 | 0) 110509058 Asterisk A appears to correctly translate correct DIALSTATUS and HANGUPCAUSE from SIP provider via IAX2 trunk (ie SIP to IAX2 appears to work correctly): {noformat} -- Executing [27110509058@custom-freepbx-a2billing:1] DeadAGI("IAX2/0117211900-2043", "a2billing.php,1") in new stack [2014-07-01 02:17:16] WARNING[8957][C-0006a204]: res_agi.c:4005 deadagi_exec: DeadAGI has been deprecated, please use AGI in all cases! -- Launched AGI Script /var/lib/asterisk/agi-bin/a2billing.php -- AGI Script Executing Application: (DIAL) Options: (SIP/ECN/0110509058,60,HRL(36000000:61000:30000)) > Limit Data for this call: > timelimit = 36000000 ms (36000.000 s) > play_warning = 61000 ms (61.000 s) > play_to_caller = yes > play_to_callee = no > warning_freq = 30000 ms (30.000 s) > start_sound = > warning_sound = timeleft > end_sound = == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 -- Called SIP/ECN/0110509058 -- Got SIP response 486 "Busy here" back from 14.122.0.33:5060 -- SIP/ECN-0006ca27 is busy == Everyone is busy/congested at this time (1:1/0/0) -- AGI Script Executing Application: (Busy) Options: (1) -- <IAX2/0117211900-2043>AGI Script a2billing.php completed, returning 4 == Spawn extension (custom-freepbx-a2billing, 27110509058, 1) exited non-zero on 'IAX2/0117211900-2043' -- Executing [h@custom-freepbx-a2billing:1] NoOp("IAX2/0117211900-2043", "h: Dial status: BUSY Hangup cause: 17") in new stack -- Executing [h@custom-freepbx-a2billing:2] Set("IAX2/0117211900-2043", "RC=17") in new stack -- Executing [h@custom-freepbx-a2billing:3] ExecIf("IAX2/0117211900-2043", "1?Playtones(busy)") in new stack -- Executing [h@custom-freepbx-a2billing:4] ExecIf("IAX2/0117211900-2043", "1?Wait(20)") in new stack == Spawn extension (custom-freepbx-a2billing, h, 4) exited non-zero on 'IAX2/0117211900-2043' -- Hungup 'IAX2/0117211900-2043' {noformat} Asterisk B appears to correct identify 'CAUSE CODE' as 17 on the IAX2 trunk but SIP end point gets HANGUP CAUSE 16 (normal clearing). The interesting bits: {noformat} Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 003 Type: CONTROL Subclass: BUSY Timestamp: 01391ms SCall: 02043 DCall: 24152 [192.25.69.236:4569] Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 005 Type: IAX Subclass: ACK Timestamp: 01391ms SCall: 24152 DCall: 02043 [192.25.69.236:4569] -- Executing [h@macro-dialout-trunk:1] NoOp("SIP/1904-00009c84", "h: Dial status: ANSWER Hangup cause: 16") in new stack <snip> Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 005 Type: IAX Subclass: HANGUP Timestamp: 01419ms SCall: 24152 DCall: 02043 [192.25.69.236:4569] CAUSE CODE : 17 {noformat} Full debug on both IAX2 and SIP traffic, on Asterisk B system. Please note that I had attempted to add busy call handling (the '0?Goto(macro-dialout-trunk,s-BUSY,1)' piece) but this doesn't work as the call had already been hungup: {noformat} -- Executing [s@macro-dialout-trunk:22] Dial("SIP/1904-00009c84", "IAX2/Syrex/0110509058,300,tL(10800000:300000)") in new stack > Limit Data for this call: > timelimit = 10800000 ms (10800.000 s) > play_warning = 300000 ms (300.000 s) > play_to_caller = yes > play_to_callee = no > warning_freq = 0 ms (0.000 s) > start_sound = > warning_sound = timeleft > end_sound = -- Called IAX2/Syrex/0110509058 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00003ms SCall: 24152 DCall: 00000 [192.25.69.236:4569] VERSION : 2 CALLED NUMBER : 0110509058 CODEC_PREFS : (g729) CALLING NUMBER : 0861179739 CALLING PRESNTN : 0 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : Syrex LANGUAGE : en USERNAME : 0117211900 FORMAT : 256 FORMAT2 : g729 CAPABILITY : 256 CAPABILITY2 : g729 ADSICPE : 2 DATE TIME : 2014-07-01 02:17:16 VARIABLE : X-CallerID="Syrex" <0861179739> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN Timestamp: 00003ms SCall: 00001 DCall: 24152 [192.25.69.236:4569] CALLTOKEN : 51 bytes Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00009ms SCall: 24152 DCall: 00000 [192.25.69.236:4569] VERSION : 2 CALLED NUMBER : 0110509058 CODEC_PREFS : (g729) CALLING NUMBER : 0861179739 CALLING PRESNTN : 0 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : Syrex LANGUAGE : en USERNAME : 0117211900 FORMAT : 256 FORMAT2 : g729 CAPABILITY : 256 CAPABILITY2 : g729 ADSICPE : 2 DATE TIME : 2014-07-01 02:17:16 VARIABLE : X-CallerID="Syrex" <0861179739> CALLTOKEN : 51 bytes Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: AUTHREQ Timestamp: 00014ms SCall: 02043 DCall: 24152 [192.25.69.236:4569] AUTHMETHODS : 3 CHALLENGE : \x37\x38\x33\x33\x32\x30\x38\x34\x38 USERNAME : 0117211900 Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: AUTHREP Timestamp: 00019ms SCall: 24152 DCall: 02043 [192.25.69.236:4569] MD5 RESULT : bc48027f52791960c81018f71a8e17e2 Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACCEPT Timestamp: 00022ms SCall: 02043 DCall: 24152 [192.25.69.236:4569] FORMAT : 256 FORMAT2 : g729 -- Call accepted by 192.25.69.236 (format g729) -- Format for call is (g729) Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 00022ms SCall: 24152 DCall: 02043 [192.25.69.236:4569] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER Timestamp: 00025ms SCall: 02043 DCall: 24152 [192.25.69.236:4569] Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00025ms SCall: 24152 DCall: 02043 [192.25.69.236:4569] Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: (255?) Timestamp: 00028ms SCall: 02043 DCall: 24152 [192.25.69.236:4569] Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 004 Type: IAX Subclass: ACK Timestamp: 00028ms SCall: 24152 DCall: 02043 [192.25.69.236:4569] -- IAX2/Syrex-24152 answered SIP/1904-00009c84 Audio is at 13120 Adding codec 100004 (alaw) to SDP Adding codec 100003 (ulaw) to SDP Adding codec 100008 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP <--- Reliably Transmitting (NAT) to 192.168.10.53:11468 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.10.53:11468;branch=z9hG4bK-d8754z-f01dde7fb476187a-1---d8754z-;received=192.168.10.53;rport=11468 From: "David Herselman"<sip:1904@lair.co.za>;tag=455f2257 To: "0110509058"<sip:0110509058@lair.co.za>;tag=as3b114d0c Call-ID: NTBkYjFmYTYwNmNiMDZmN2E5ZWU1ZDkwM2JiNWExMGU. CSeq: 2 INVITE Server: FPBX-2.11.0(11.9.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: <sip:0110509058@192.168.1.11:5060> P-Asserted-Identity: "CID:0861179739" <sip:0110509058@lair.co.za> Content-Type: application/sdp Content-Length: 306 v=0 o=root 1222277392 1222277392 IN IP4 192.168.1.11 s=Asterisk PBX 11.9.0 c=IN IP4 192.168.1.11 t=0 0 m=audio 13120 RTP/AVP 8 0 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> > 0x534b9d0 -- Probation passed - setting RTP source address to 192.168.10.53:28102 Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 004 Type: VOICE Subclass: 136 Timestamp: 00242ms SCall: 24152 DCall: 02043 [192.25.69.236:4569] Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00242ms SCall: 02043 DCall: 24152 [192.25.69.236:4569] Retransmitting #1 (NAT) to 192.168.10.53:11468: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.10.53:11468;branch=z9hG4bK-d8754z-f01dde7fb476187a-1---d8754z-;received=192.168.10.53;rport=11468 From: "David Herselman"<sip:1904@lair.co.za>;tag=455f2257 To: "0110509058"<sip:0110509058@lair.co.za>;tag=as3b114d0c Call-ID: NTBkYjFmYTYwNmNiMDZmN2E5ZWU1ZDkwM2JiNWExMGU. CSeq: 2 INVITE Server: FPBX-2.11.0(11.9.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: <sip:0110509058@192.168.1.11:5060> P-Asserted-Identity: "CID:0861179739" <sip:0110509058@lair.co.za> Content-Type: application/sdp Content-Length: 306 v=0 o=root 1222277392 1222277392 IN IP4 192.168.1.11 s=Asterisk PBX 11.9.0 c=IN IP4 192.168.1.11 t=0 0 m=audio 13120 RTP/AVP 8 0 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- <--- SIP read from UDP:192.168.10.53:11468 ---> ACK sip:0110509058@192.168.1.11:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.10.53:11468;branch=z9hG4bK-d8754z-196e134d872d0263-1---d8754z-;rport Max-Forwards: 70 Contact: <sip:1904@192.168.10.53:11468> To: "0110509058"<sip:0110509058@lair.co.za>;tag=as3b114d0c From: "David Herselman"<sip:1904@lair.co.za>;tag=455f2257 Call-ID: NTBkYjFmYTYwNmNiMDZmN2E5ZWU1ZDkwM2JiNWExMGU. CSeq: 2 ACK User-Agent: eyeBeam release 1102u stamp 52344 Authorization: Digest username="1904",realm="asterisk",nonce="66728a2b",uri="sip:0110509058@lair.co.za",response="fcee593a5da05f1858473837077ed8a4",algorithm=MD5 Content-Length: 0 <-------------> --- (11 headers 0 lines) --- <--- SIP read from UDP:192.168.10.53:11468 ---> ACK sip:0110509058@192.168.1.11:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.10.53:11468;branch=z9hG4bK-d8754z-196e134d872d0263-1---d8754z-;rport Max-Forwards: 70 Contact: <sip:1904@192.168.10.53:11468> To: "0110509058"<sip:0110509058@lair.co.za>;tag=as3b114d0c From: "David Herselman"<sip:1904@lair.co.za>;tag=455f2257 Call-ID: NTBkYjFmYTYwNmNiMDZmN2E5ZWU1ZDkwM2JiNWExMGU. CSeq: 2 ACK User-Agent: eyeBeam release 1102u stamp 52344 Authorization: Digest username="1904",realm="asterisk",nonce="66728a2b",uri="sip:0110509058@lair.co.za",response="fcee593a5da05f1858473837077ed8a4",algorithm=MD5 Content-Length: 0 <-------------> --- (11 headers 0 lines) --- Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 003 Type: CONTROL Subclass: BUSY Timestamp: 01391ms SCall: 02043 DCall: 24152 [192.25.69.236:4569] Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 005 Type: IAX Subclass: ACK Timestamp: 01391ms SCall: 24152 DCall: 02043 [192.25.69.236:4569] -- Executing [h@macro-dialout-trunk:1] NoOp("SIP/1904-00009c84", "h: Dial status: ANSWER Hangup cause: 16") in new stack -- Executing [h@macro-dialout-trunk:2] ExecIf("SIP/1904-00009c84", "0?Goto(macro-dialout-trunk,s-BUSY,1)") in new stack -- Executing [h@macro-dialout-trunk:3] Macro("SIP/1904-00009c84", "hangupcall,") in new stack -- Executing [s@macro-hangupcall:1] GotoIf("SIP/1904-00009c84", "1?theend") in new stack -- Goto (macro-hangupcall,s,3) -- Executing [s@macro-hangupcall:3] ExecIf("SIP/1904-00009c84", "0?Set(CDR(recordingfile)=)") in new stack -- Executing [s@macro-hangupcall:4] Hangup("SIP/1904-00009c84", "") in new stack == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/1904-00009c84' in macro 'hangupcall' == Spawn extension (macro-dialout-trunk, h, 3) exited non-zero on 'SIP/1904-00009c84' -- Hungup 'IAX2/Syrex-24152' Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 005 Type: IAX Subclass: HANGUP Timestamp: 01419ms SCall: 24152 DCall: 02043 [192.25.69.236:4569] CAUSE CODE : 17 == Spawn extension (macro-dialout-trunk, s, 22) exited non-zero on 'SIP/1904-00009c84' in macro 'dialout-trunk' == Spawn extension (from-internal, 0110509058, 6) exited non-zero on 'SIP/1904-00009c84' Scheduling destruction of SIP dialog 'NTBkYjFmYTYwNmNiMDZmN2E5ZWU1ZDkwM2JiNWExMGU.' in 6400 ms (Method: ACK) set_destination: Parsing <sip:1904@192.168.10.53:11468> for address/port to send to set_destination: set destination to 192.168.10.53:11468 Reliably Transmitting (NAT) to 192.168.10.53:11468: BYE sip:1904@192.168.10.53:11468 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK0950d4f3;rport Max-Forwards: 70 From: "0110509058"<sip:0110509058@lair.co.za>;tag=as3b114d0c To: "David Herselman"<sip:1904@lair.co.za>;tag=455f2257 Call-ID: NTBkYjFmYTYwNmNiMDZmN2E5ZWU1ZDkwM2JiNWExMGU. CSeq: 102 BYE User-Agent: FPBX-2.11.0(11.9.0) Proxy-Authorization: Digest username="1904", realm="asterisk", algorithm=MD5, uri="sip:lair.co.za", nonce="66728a2b", response="749618b1eff00313deaf0f456f32dc70" X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- == Extension Changed 1904[ext-local] new state Idle for Notify User 1964 == MixMonitor close filestream (mixed) == End MixMonitor Recording SIP/1904-00009c84 == Extension Changed 1904[ext-local] new state Idle for Notify User 1966 == Extension Changed 1904[ext-local] new state Idle for Notify User 1927 == Extension Changed 1904[ext-local] new state Idle for Notify User 1946 Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: IAX Subclass: ACK Timestamp: 01419ms SCall: 02043 DCall: 24152 [192.25.69.236:4569] Retransmitting #1 (NAT) to 192.168.10.53:11468: BYE sip:1904@192.168.10.53:11468 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK0950d4f3;rport Max-Forwards: 70 From: "0110509058"<sip:0110509058@lair.co.za>;tag=as3b114d0c To: "David Herselman"<sip:1904@lair.co.za>;tag=455f2257 Call-ID: NTBkYjFmYTYwNmNiMDZmN2E5ZWU1ZDkwM2JiNWExMGU. CSeq: 102 BYE User-Agent: FPBX-2.11.0(11.9.0) Proxy-Authorization: Digest username="1904", realm="asterisk", algorithm=MD5, uri="sip:lair.co.za", nonce="66728a2b", response="749618b1eff00313deaf0f456f32dc70" X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- <--- SIP read from UDP:192.168.10.53:11468 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK0950d4f3;rport=5060 Contact: <sip:1904@192.168.10.53:11468> To: "David Herselman"<sip:1904@lair.co.za>;tag=455f2257 From: "0110509058"<sip:0110509058@lair.co.za>;tag=as3b114d0c Call-ID: NTBkYjFmYTYwNmNiMDZmN2E5ZWU1ZDkwM2JiNWExMGU. CSeq: 102 BYE User-Agent: eyeBeam release 1102u stamp 52344 Content-Length: 0 <-------------> --- (9 headers 0 lines) --- SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog 'NTBkYjFmYTYwNmNiMDZmN2E5ZWU1ZDkwM2JiNWExMGU.' Method: ACK <--- SIP read from UDP:192.168.10.53:11468 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK0950d4f3;rport=5060 Contact: <sip:1904@192.168.10.53:11468> To: "David Herselman"<sip:1904@lair.co.za>;tag=455f2257 From: "0110509058"<sip:0110509058@lair.co.za>;tag=as3b114d0c Call-ID: NTBkYjFmYTYwNmNiMDZmN2E5ZWU1ZDkwM2JiNWExMGU. CSeq: 102 BYE User-Agent: eyeBeam release 1102u stamp 52344 Content-Length: 0 {noformat} | ||||
| Comments: | By: Rusty Newton (rnewton) 2014-07-01 20:14:40.069-0500 Can you post your configuration for the IAX trunks and SIP endpoints so that the scenario can be easily replicated? That means, please simplify the configuration and if you can test it without your provider involved to make sure the same behavior happens. By: David Herselman (bbs2web) 2014-07-02 14:57:29.482-0500 We manage our Asterisk installations by installing and using the FreePBX GUI. FreePBX generates various iax and sip configuration files, which are pulled in by iax.conf and sip.conf, so I've combined the switches and options in the exact order Asterisk's IAX and SIP modules essentially sees them. I fully understand that this bug involves a fairly complex setup requirement and can gladly provide a test trunk as re-creating the bug essentially requires a SIP trunk answering busy on Asterisk A, an IAX2 trunk between Asterisk A and Asterisk B and a SIP end point on Asterisk B. Asterisk A - IAX2 configuration: /etc/asterisk/iax.conf: {noformat} [general] mailboxdetail=yes tos=ef disallow=all allow=ulaw allow=alaw allow=gsm calltokenoptional=10.0.0.0/255.0.0.0 calltokenoptional=172.16.0.0/255.240.0.0 calltokenoptional=192.168.0.0/255.255.0.0 allow=adpcm allow=g729 allow=g723 allow=g722 allow=gsm allow=slin allow=speex allow=lpc10 allow=ilbc allow=g726aal2 allow=g726 allow=h261 allow=h263 allow=h263p allow=h264 videosupport=yes tcpenable=yes [guest] disallow=ulaw,alaw,adpcm type=user context=from-trunk [0117211900] deny=0.0.0.0/0.0.0.0 disallow=all secret=******* transfer=no context=from-internal host=dynamic type=friend port=4569 qualify=yes allow=g729 dial=IAX2/0117211900/0117211900 accountcode=******* mailbox=0117211900@device permit=0.0.0.0/0.0.0.0 requirecalltoken=yes callerid=Syrex <0117211900> setvar=REALCALLERIDNUM=0117211900 trunk=yes username=Syrex trunktimestamps=yes jitterbuffer=yes {noformat} Asterisk A - SIP configuration: /etc/asterisk/sip.conf: {noformat} [general] faxdetect=no vmexten=*97 context=from-sip-external callerid=Unknown notifyringing=yes notifyhold=yes tos_sip=cs3 tos_audio=ef tos_video=af41 alwaysauthreject=yes useragent=FPBX-2.11.0(11.9.0) disallow=all allow=ulaw allow=alaw allow=gsm localnet=10.0.0.0/255.0.0.0 localnet=172.16.0.0/255.240.0.0 localnet=192.25.69.128/255.255.255.128 localnet=192.168.0.0/255.255.0.0 externhost=sip.syrex.co.za externrefresh=10 fromdomain=syrex.co.za nat=yes qualify=yes canreinvite=yes registerattempts=0 t38pt_udptl=yes,redundancy,maxdatagram=400 t38pt_usertpsource=yes context=custom-from-sip-external ignoreregexpire=yes maxexpiry=300 notifycid=ignore-context rtptimeout=60 rtpholdtimeout=1800 accept_outofcall_message=yes outofcall_message_context=astsms register=Syr-Jhb-001:*******@14.122.0.33 allow=adpcm allow=g729 allow=g723 allow=g722 allow=gsm allow=slin allow=speex allow=lpc10 allow=ilbc allow=g726aal2 allow=g726 allow=h261 allow=h263 allow=h263p allow=h264 videosupport=yes tcpenable=yes transport=udp,tcp [ECN] disallow=all allow=g729,alaw host=14.122.0.33 canreinvite=yes username=Syr-Jhb-001 secret=******* sendrpid=yes type=peer insecure=port,invite context=from-pstn {noformat} Asterisk B - IAX2 configuration: /etc/asterisk/iax.conf: {noformat} [general] mailboxdetail=yes tos=ef disallow=all allow=ulaw allow=alaw allow=gsm calltokenoptional=10.0.0.0/255.0.0.0 calltokenoptional=172.16.0.0/255.240.0.0 calltokenoptional=192.168.0.0/255.255.0.0 register=0117211900:*******@192.25.69.236 allow=adpcm allow=g729 allow=g723 allow=g722 allow=gsm allow=slin allow=speex allow=lpc10 allow=ilbc allow=g726aal2 allow=g726 allow=h261 allow=h263 allow=h263p allow=h264 videosupport=yes tcpenable=yes [guest] disallow=ulaw,alaw,adpcm type=user context=from-trunk [Syrex] disallow=all host=192.25.69.236 username=0117211900 secret=******* requirecalltoken=yes qualify=yes allow=g729 trunk=yes trunktimestamps=yes jitterbuffer=yes transfer=no type=friend context=from-pstn {noformat} Asterisk B - SIP configuration: /etc/asterisk/sip.conf: {noformat} [general] faxdetect=no vmexten=*97 context=from-sip-external callerid=Unknown notifyringing=yes notifyhold=yes tos_sip=cs3 tos_audio=ef tos_video=af41 alwaysauthreject=yes useragent=FPBX-2.11.0(11.9.0) disallow=all allow=alaw allow=gsm allow=ulaw localnet=10.0.0.0/255.0.0.0 localnet=172.16.0.0/255.240.0.0 localnet=192.168.0.0/255.255.0.0 externhost=dynamic2.lair.co.za externrefresh=10 fromdomain=lair.co.za nat=yes qualify=yes canreinvite=no registerattempts=0 t38pt_udptl=yes,redundancy,maxdatagram=400 t38pt_usertpsource=yes context=custom-from-sip-external notifycid=ignore-context rtptimeout=60 rtpholdtimeout=1800 accept_outofcall_message=yes outofcall_message_context=astsms allow=adpcm allow=g729 allow=g723 allow=g722 allow=gsm allow=slin allow=speex allow=lpc10 allow=ilbc allow=g726aal2 allow=g726 allow=h261 allow=h263 allow=h263p allow=h264 videosupport=yes tcpenable=yes transport=udp,tcp [1904] deny=0.0.0.0/0.0.0.0 secret=******* dtmfmode=rfc2833 canreinvite=no context=from-internal host=dynamic trustrpid=yes sendrpid=pai type=friend nat=yes port=5060 qualify=yes qualifyfreq=60 transport=udp encryption=no callgroup=1 pickupgroup=1 dial=SIP/1904 mailbox=1904@default permit=0.0.0.0/0.0.0.0 callerid=David Herselman <1904> callcounter=yes faxdetect=no cc_monitor_policy=generic {noformat} By: David Herselman (bbs2web) 2014-07-02 15:21:12.781-0500 Creating a 'Misc Application' on Asterisk A, with a bogus number of 0113334444, which terminates a call with a busy signal the SIP end point on Asterisk B correctly plays the right tone: Asterisk A verbose output: {noformat} -- Accepting AUTHENTICATED call from 196.15.189.26: -- > requested format = g729, -- > requested prefs = (g729), -- > actual format = g729, -- > host prefs = (g729), -- > priority = mine -- Executing [0113334444@from-internal:1] NoOp("IAX2/0117211900-9429", "Running miscapp 1: Testing Busy") in new stack -- Executing [0113334444@from-internal:2] Macro("IAX2/0117211900-9429", "user-callerid,") in new stack -- Executing [s@macro-user-callerid:1] Set("IAX2/0117211900-9429", "TOUCH_MONITOR=1404331422.96") in new stack -- Executing [s@macro-user-callerid:2] Set("IAX2/0117211900-9429", "AMPUSER=0117211900") in new stack -- Executing [s@macro-user-callerid:3] GotoIf("IAX2/0117211900-9429", "0?report") in new stack -- Executing [s@macro-user-callerid:4] ExecIf("IAX2/0117211900-9429", "0?Set(REALCALLERIDNUM=0117211900)") in new stack -- Executing [s@macro-user-callerid:5] Set("IAX2/0117211900-9429", "AMPUSER=0117211900") in new stack -- Executing [s@macro-user-callerid:6] GotoIf("IAX2/0117211900-9429", "0?limit") in new stack -- Executing [s@macro-user-callerid:7] Set("IAX2/0117211900-9429", "AMPUSERCIDNAME=Syrex") in new stack -- Executing [s@macro-user-callerid:8] GotoIf("IAX2/0117211900-9429", "0?report") in new stack -- Executing [s@macro-user-callerid:9] Set("IAX2/0117211900-9429", "AMPUSERCID=0861179739") in new stack -- Executing [s@macro-user-callerid:10] Set("IAX2/0117211900-9429", "__DIAL_OPTIONS=tL(10800000:300000)") in new stack -- Executing [s@macro-user-callerid:11] Set("IAX2/0117211900-9429", "CALLERID(all)="Syrex" <0861179739>") in new stack -- Executing [s@macro-user-callerid:12] GotoIf("IAX2/0117211900-9429", "0?limit") in new stack -- Executing [s@macro-user-callerid:13] ExecIf("IAX2/0117211900-9429", "0?Set(GROUP(concurrency_limit)=0117211900)") in new stack -- Executing [s@macro-user-callerid:14] ExecIf("IAX2/0117211900-9429", "0?Set(CHANNEL(language)=)") in new stack -- Executing [s@macro-user-callerid:15] GosubIf("IAX2/0117211900-9429", "7?sub-ccss,s,1(from-internal,)") in new stack -- Executing [s@sub-ccss:1] ExecIf("IAX2/0117211900-9429", "0?Return()") in new stack -- Executing [s@sub-ccss:2] Set("IAX2/0117211900-9429", "CCSS_SETUP=TRUE") in new stack -- Executing [s@sub-ccss:3] GosubIf("IAX2/0117211900-9429", "0?monitor_config,1(from-internal,):monitor_default,1(from-internal,)") in new stack -- Executing [monitor_default@sub-ccss:1] GotoIf("IAX2/0117211900-9429", "0?is_exten") in new stack -- Executing [monitor_default@sub-ccss:2] StackPop("IAX2/0117211900-9429", "") in new stack -- Executing [monitor_default@sub-ccss:3] Return("IAX2/0117211900-9429", "FALSE") in new stack -- Executing [s@macro-user-callerid:16] GotoIf("IAX2/0117211900-9429", "0?continue") in new stack -- Executing [s@macro-user-callerid:17] Set("IAX2/0117211900-9429", "__TTL=64") in new stack -- Executing [s@macro-user-callerid:18] GotoIf("IAX2/0117211900-9429", "1?continue") in new stack -- Goto (macro-user-callerid,s,29) -- Executing [s@macro-user-callerid:29] Set("IAX2/0117211900-9429", "CALLERID(number)=0861179739") in new stack -- Executing [s@macro-user-callerid:30] Set("IAX2/0117211900-9429", "CALLERID(name)=Syrex") in new stack -- Executing [s@macro-user-callerid:31] Set("IAX2/0117211900-9429", "CDR(cnum)=0861179739") in new stack -- Executing [s@macro-user-callerid:32] Set("IAX2/0117211900-9429", "CDR(cnam)=Syrex") in new stack -- Executing [s@macro-user-callerid:33] Set("IAX2/0117211900-9429", "CHANNEL(language)=en") in new stack -- Executing [0113334444@from-internal:3] Goto("IAX2/0117211900-9429", "app-blackhole,busy,1") in new stack -- Goto (app-blackhole,busy,1) -- Executing [busy@app-blackhole:1] NoOp("IAX2/0117211900-9429", "Blackhole Dest: Busy") in new stack -- Executing [busy@app-blackhole:2] Busy("IAX2/0117211900-9429", "20") in new stack == Spawn extension (app-blackhole, busy, 2) exited non-zero on 'IAX2/0117211900-9429' -- Hungup 'IAX2/0117211900-9429' {noformat} Asterisk B gets the 'BUSY' immediately, before first receiving an 'ANSWER' as it did when the call is forwarded via a trunk. The interesting bits: {noformat} -- Call accepted by 192.25.69.236 (format g729) -- Format for call is (g729) Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 00012ms SCall: 26724 DCall: 09429 [192.25.69.236:4569] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: BUSY Timestamp: 00015ms SCall: 09429 DCall: 26724 [192.25.69.236:4569] Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00015ms SCall: 26724 DCall: 09429 [192.25.69.236:4569] -- IAX2/Syrex-26724 is busy -- Hungup 'IAX2/Syrex-26724' Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: HANGUP Timestamp: 00082ms SCall: 26724 DCall: 09429 [192.25.69.236:4569] CAUSE CODE : 17 {noformat} Full debug on both IAX2 and SIP traffic, on Asterisk B system: {noformat} -- Executing [s@macro-dialout-trunk:22] Dial("SIP/1904-0000a920", "IAX2/Syrex/0113334444,300,tL(10800000:300000)") in new stack > Limit Data for this call: > timelimit = 10800000 ms (10800.000 s) > play_warning = 300000 ms (300.000 s) > play_to_caller = yes > play_to_callee = no > warning_freq = 0 ms (0.000 s) > start_sound = > warning_sound = timeleft > end_sound = -- Called IAX2/Syrex/0113334444 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00009ms SCall: 26724 DCall: 00000 [192.25.69.236:4569] VERSION : 2 CALLED NUMBER : 0113334444 CODEC_PREFS : (g729) CALLING NUMBER : 0861179739 CALLING PRESNTN : 0 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : Syrex LANGUAGE : en USERNAME : 0117211900 FORMAT : 256 FORMAT2 : g729 CAPABILITY : 256 CAPABILITY2 : g729 ADSICPE : 2 DATE TIME : 2014-07-02 22:03:42 VARIABLE : X-CallerID="Syrex" <0861179739> == Begin MixMonitor Recording SIP/1904-0000a920 Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN Timestamp: 00009ms SCall: 00001 DCall: 26724 [192.25.69.236:4569] CALLTOKEN : 51 bytes Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00017ms SCall: 26724 DCall: 00000 [192.25.69.236:4569] VERSION : 2 CALLED NUMBER : 0113334444 CODEC_PREFS : (g729) CALLING NUMBER : 0861179739 CALLING PRESNTN : 0 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : Syrex LANGUAGE : en USERNAME : 0117211900 FORMAT : 256 FORMAT2 : g729 CAPABILITY : 256 CAPABILITY2 : g729 ADSICPE : 2 DATE TIME : 2014-07-02 22:03:42 VARIABLE : X-CallerID="Syrex" <0861179739> CALLTOKEN : 51 bytes Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: AUTHREQ Timestamp: 00004ms SCall: 09429 DCall: 26724 [192.25.69.236:4569] AUTHMETHODS : 3 CHALLENGE : \x32\x33\x31\x36\x31\x30\x30\x33\x31 USERNAME : 0117211900 Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: AUTHREP Timestamp: 00027ms SCall: 26724 DCall: 09429 [192.25.69.236:4569] MD5 RESULT : 01c783bee1947665476f45fa9c3fb603 Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACCEPT Timestamp: 00012ms SCall: 09429 DCall: 26724 [192.25.69.236:4569] FORMAT : 256 FORMAT2 : g729 -- Call accepted by 192.25.69.236 (format g729) -- Format for call is (g729) Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 00012ms SCall: 26724 DCall: 09429 [192.25.69.236:4569] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: BUSY Timestamp: 00015ms SCall: 09429 DCall: 26724 [192.25.69.236:4569] Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00015ms SCall: 26724 DCall: 09429 [192.25.69.236:4569] -- IAX2/Syrex-26724 is busy -- Hungup 'IAX2/Syrex-26724' Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: HANGUP Timestamp: 00082ms SCall: 26724 DCall: 09429 [192.25.69.236:4569] CAUSE CODE : 17 == Everyone is busy/congested at this time (1:1/0/0) -- Executing [s@macro-dialout-trunk:23] NoOp("SIP/1904-0000a920", "Dial failed for some reason with DIALSTATUS = BUSY and HANGUPCAUSE = 17") in new stack -- Executing [s@macro-dialout-trunk:24] GotoIf("SIP/1904-0000a920", "0?continue,1:s-BUSY,1") in new stack -- Goto (macro-dialout-trunk,s-BUSY,1) -- Executing [s-BUSY@macro-dialout-trunk:1] NoOp("SIP/1904-0000a920", "Dial failed due to trunk reporting BUSY - giving up") in new stack -- Executing [s-BUSY@macro-dialout-trunk:2] PlayTones("SIP/1904-0000a920", "busy") in new stack [2014-07-02 22:03:42] WARNING[26151][C-0000627b]: translate.c:343 framein: no samples for alawtolin -- Executing [s-BUSY@macro-dialout-trunk:3] Busy("SIP/1904-0000a920", "20") in new stack <--- Reliably Transmitting (NAT) to 192.168.10.53:46522 ---> SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 192.168.10.53:46522;branch=z9hG4bK-d8754z-e1231c53192ad628-1---d8754z-;received=192.168.10.53;rport=46522 From: "David Herselman"<sip:1904@lair.co.za>;tag=9878f509 To: "0113334444"<sip:0113334444@lair.co.za>;tag=as3921fe5b Call-ID: NjFmNDY5NWNmZGEzZTE4MjhlNzg0YTIxYzI4ZDA2NjE. CSeq: 2 INVITE Server: FPBX-2.11.0(11.9.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer X-Asterisk-HangupCause: User busy X-Asterisk-HangupCauseCode: 17 Content-Length: 0 <------------> == Spawn extension (macro-dialout-trunk, s-BUSY, 3) exited non-zero on 'SIP/1904-0000a920' in macro 'dialout-trunk' == Spawn extension (from-internal, 0113334444, 6) exited non-zero on 'SIP/1904-0000a920' -- Executing [h@from-internal:1] Hangup("SIP/1904-0000a920", "") in new stack == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/1904-0000a920' == Extension Changed 1904[ext-local] new state Idle for Notify User 1964 == Extension Changed 1904[ext-local] new state Idle for Notify User 1900 Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00082ms SCall: 09429 DCall: 26724 [192.25.69.236:4569] <--- SIP read from UDP:192.168.10.53:46522 ---> ACK sip:0113334444@lair.co.za SIP/2.0 Via: SIP/2.0/UDP 192.168.10.53:46522;branch=z9hG4bK-d8754z-e1231c53192ad628-1---d8754z-;rport To: "0113334444"<sip:0113334444@lair.co.za>;tag=as3921fe5b From: "David Herselman"<sip:1904@lair.co.za>;tag=9878f509 Call-ID: NjFmNDY5NWNmZGEzZTE4MjhlNzg0YTIxYzI4ZDA2NjE. CSeq: 2 ACK Content-Length: 0 <-------------> --- (7 headers 0 lines) --- Really destroying SIP dialog 'NjFmNDY5NWNmZGEzZTE4MjhlNzg0YTIxYzI4ZDA2NjE.' Method: ACK == MixMonitor close filestream (mixed) == End MixMonitor Recording SIP/1904-0000a920 Reliably Transmitting (NAT) to 192.168.10.53:46522: NOTIFY sip:1904@192.168.10.53:46522 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK5a0f042a;rport Max-Forwards: 70 Route: <sip:1904@192.168.10.53:46522> From: "Unknown" <sip:Unknown@lair.co.za>;tag=as61892e63 To: <sip:1904@192.168.10.53:46522>;tag=d752b476 Contact: <sip:Unknown@192.168.1.11:5060> Call-ID: NDcwZWI1YTlkOThjYjdkNGY4Njc5Y2JkZjExZTY4ZDk. CSeq: 109 NOTIFY User-Agent: FPBX-2.11.0(11.9.0) Event: message-summary Content-Type: application/simple-message-summary Subscription-State: active Content-Length: 85 Messages-Waiting: no Message-Account: sip:*97@lair.co.za Voice-Message: 0/0 (0/0) --- Retransmitting #1 (NAT) to 192.168.10.53:46522: NOTIFY sip:1904@192.168.10.53:46522 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK5a0f042a;rport Max-Forwards: 70 Route: <sip:1904@192.168.10.53:46522> From: "Unknown" <sip:Unknown@lair.co.za>;tag=as61892e63 To: <sip:1904@192.168.10.53:46522>;tag=d752b476 Contact: <sip:Unknown@192.168.1.11:5060> Call-ID: NDcwZWI1YTlkOThjYjdkNGY4Njc5Y2JkZjExZTY4ZDk. CSeq: 109 NOTIFY User-Agent: FPBX-2.11.0(11.9.0) Event: message-summary Content-Type: application/simple-message-summary Subscription-State: active Content-Length: 85 Messages-Waiting: no Message-Account: sip:*97@lair.co.za Voice-Message: 0/0 (0/0) --- <--- SIP read from UDP:192.168.10.53:46522 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK5a0f042a;rport=5060 Contact: <sip:1904@192.168.10.53:46522> To: <sip:1904@192.168.10.53:46522>;tag=d752b476 From: "Unknown"<sip:Unknown@lair.co.za>;tag=as61892e63 Call-ID: NDcwZWI1YTlkOThjYjdkNGY4Njc5Y2JkZjExZTY4ZDk. CSeq: 109 NOTIFY User-Agent: eyeBeam release 1102u stamp 52344 Content-Length: 0 <-------------> --- (9 headers 0 lines) --- <--- SIP read from UDP:192.168.10.53:46522 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK5a0f042a;rport=5060 Contact: <sip:1904@192.168.10.53:46522> To: <sip:1904@192.168.10.53:46522>;tag=d752b476 From: "Unknown"<sip:Unknown@lair.co.za>;tag=as61892e63 Call-ID: NDcwZWI1YTlkOThjYjdkNGY4Njc5Y2JkZjExZTY4ZDk. CSeq: 109 NOTIFY User-Agent: eyeBeam release 1102u stamp 52344 Content-Length: 0 <-------------> --- (9 headers 0 lines) --- {noformat} By: David Herselman (bbs2web) 2014-07-02 15:49:54.141-0500 Herewith full SIP & IAX2 debug information from Asterisk A whilst processing a call to a busy destination, as detailed in original report: {noformat} Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00010ms SCall: 28444 DCall: 00000 [196.15.189.26:4569] VERSION : 2 CALLED NUMBER : 0110509058 CODEC_PREFS : (g729) CALLING NUMBER : 0861179739 CALLING PRESNTN : 0 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : Syrex LANGUAGE : en USERNAME : 0117211900 FORMAT : 256 FORMAT2 : g729 CAPABILITY : 256 CAPABILITY2 : g729 ADSICPE : 2 DATE TIME : 2014-07-02 22:23:26 VARIABLE : X-CallerID="Syrex" <0861179739> Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN Timestamp: 00010ms SCall: 00001 DCall: 28444 [196.15.189.26:4569] CALLTOKEN : 51 bytes Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00019ms SCall: 28444 DCall: 00000 [196.15.189.26:4569] VERSION : 2 CALLED NUMBER : 0110509058 CODEC_PREFS : (g729) CALLING NUMBER : 0861179739 CALLING PRESNTN : 0 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : Syrex LANGUAGE : en USERNAME : 0117211900 FORMAT : 256 FORMAT2 : g729 CAPABILITY : 256 CAPABILITY2 : g729 ADSICPE : 2 DATE TIME : 2014-07-02 22:23:26 VARIABLE : X-CallerID="Syrex" <0861179739> CALLTOKEN : 51 bytes Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: AUTHREQ Timestamp: 00006ms SCall: 01067 DCall: 28444 [196.15.189.26:4569] AUTHMETHODS : 3 CHALLENGE : \x32\x31\x30\x37\x36\x38\x32\x37\x32 USERNAME : 0117211900 Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: AUTHREP Timestamp: 00029ms SCall: 28444 DCall: 01067 [196.15.189.26:4569] MD5 RESULT : 51a97d41d350ef6698fb7f07ec832a9f -- Accepting AUTHENTICATED call from 196.15.189.26: -- > requested format = g729, -- > requested prefs = (g729), -- > actual format = g729, -- > host prefs = (g729), -- > priority = mine Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACCEPT Timestamp: 00014ms SCall: 01067 DCall: 28444 [196.15.189.26:4569] FORMAT : 256 FORMAT2 : g729 -- Executing [0110509058@from-internal:1] Macro("IAX2/0117211900-1067", "user-callerid,LIMIT,EXTERNAL,") in new stack -- Executing [s@macro-user-callerid:1] Set("IAX2/0117211900-1067", "TOUCH_MONITOR=1404332606.99") in new stack -- Executing [s@macro-user-callerid:2] Set("IAX2/0117211900-1067", "AMPUSER=0117211900") in new stack -- Executing [s@macro-user-callerid:3] GotoIf("IAX2/0117211900-1067", "0?report") in new stack -- Executing [s@macro-user-callerid:4] ExecIf("IAX2/0117211900-1067", "0?Set(REALCALLERIDNUM=0117211900)") in new stack -- Executing [s@macro-user-callerid:5] Set("IAX2/0117211900-1067", "AMPUSER=0117211900") in new stack -- Executing [s@macro-user-callerid:6] GotoIf("IAX2/0117211900-1067", "0?limit") in new stack -- Executing [s@macro-user-callerid:7] Set("IAX2/0117211900-1067", "AMPUSERCIDNAME=Syrex") in new stack -- Executing [s@macro-user-callerid:8] GotoIf("IAX2/0117211900-1067", "0?report") in new stack -- Executing [s@macro-user-callerid:9] Set("IAX2/0117211900-1067", "AMPUSERCID=0117211900") in new stack -- Executing [s@macro-user-callerid:10] Set("IAX2/0117211900-1067", "__DIAL_OPTIONS=tL(10800000:300000)") in new stack -- Executing [s@macro-user-callerid:11] Set("IAX2/0117211900-1067", "CALLERID(all)="Syrex" <0117211900>") in new stack -- Executing [s@macro-user-callerid:12] GotoIf("IAX2/0117211900-1067", "0?limit") in new stack -- Executing [s@macro-user-callerid:13] ExecIf("IAX2/0117211900-1067", "1?Set(GROUP(concurrency_limit)=0117211900)") in new stack -- Executing [s@macro-user-callerid:14] ExecIf("IAX2/0117211900-1067", "0?Set(CHANNEL(language)=)") in new stack -- Executing [s@macro-user-callerid:15] GosubIf("IAX2/0117211900-1067", "7?sub-ccss,s,1(from-internal,)") in new stack -- Executing [s@sub-ccss:1] ExecIf("IAX2/0117211900-1067", "0?Return()") in new stack -- Executing [s@sub-ccss:2] Set("IAX2/0117211900-1067", "CCSS_SETUP=TRUE") in new stack -- Executing [s@sub-ccss:3] GosubIf("IAX2/0117211900-1067", "0?monitor_config,1(from-internal,):monitor_default,1(from-internal,)") in new stack -- Executing [monitor_default@sub-ccss:1] GotoIf("IAX2/0117211900-1067", "0?is_exten") in new stack -- Executing [monitor_default@sub-ccss:2] StackPop("IAX2/0117211900-1067", "") in new stack -- Executing [monitor_default@sub-ccss:3] Return("IAX2/0117211900-1067", "FALSE") in new stack -- Executing [s@macro-user-callerid:16] GotoIf("IAX2/0117211900-1067", "1?continue") in new stack -- Goto (macro-user-callerid,s,29) -- Executing [s@macro-user-callerid:29] Set("IAX2/0117211900-1067", "CALLERID(number)=0117211900") in new stack -- Executing [s@macro-user-callerid:30] Set("IAX2/0117211900-1067", "CALLERID(name)=Syrex") in new stack -- Executing [s@macro-user-callerid:31] Set("IAX2/0117211900-1067", "CDR(cnum)=0117211900") in new stack -- Executing [s@macro-user-callerid:32] Set("IAX2/0117211900-1067", "CDR(cnam)=Syrex") in new stack -- Executing [s@macro-user-callerid:33] Set("IAX2/0117211900-1067", "CHANNEL(language)=en") in new stack -- Executing [0110509058@from-internal:2] Set("IAX2/0117211900-1067", "MOHCLASS=default") in new stack -- Executing [0110509058@from-internal:3] Set("IAX2/0117211900-1067", "_NODEST=") in new stack -- Executing [0110509058@from-internal:4] Gosub("IAX2/0117211900-1067", "sub-record-check,s,1(out,0110509058,)") in new stack -- Executing [s@sub-record-check:1] Set("IAX2/0117211900-1067", "REC_POLICY_MODE_SAVE=") in new stack -- Executing [s@sub-record-check:2] GotoIf("IAX2/0117211900-1067", "1?check") in new stack -- Goto (sub-record-check,s,7) -- Executing [s@sub-record-check:7] Set("IAX2/0117211900-1067", "__MON_FMT=wav") in new stack -- Executing [s@sub-record-check:8] GotoIf("IAX2/0117211900-1067", "1?next") in new stack -- Goto (sub-record-check,s,11) -- Executing [s@sub-record-check:11] ExecIf("IAX2/0117211900-1067", "0?Return()") in new stack -- Executing [s@sub-record-check:12] ExecIf("IAX2/0117211900-1067", "0?Set(__REC_POLICY_MODE=)") in new stack -- Executing [s@sub-record-check:13] GotoIf("IAX2/0117211900-1067", "0?out,1") in new stack -- Executing [s@sub-record-check:14] Set("IAX2/0117211900-1067", "__REC_STATUS=INITIALIZED") in new stack -- Executing [s@sub-record-check:15] Set("IAX2/0117211900-1067", "NOW=1404332606") in new stack -- Executing [s@sub-record-check:16] Set("IAX2/0117211900-1067", "__DAY=02") in new stack -- Executing [s@sub-record-check:17] Set("IAX2/0117211900-1067", "__MONTH=07") in new stack -- Executing [s@sub-record-check:18] Set("IAX2/0117211900-1067", "__YEAR=2014") in new stack -- Executing [s@sub-record-check:19] Set("IAX2/0117211900-1067", "__TIMESTR=20140702-222326") in new stack -- Executing [s@sub-record-check:20] Set("IAX2/0117211900-1067", "__FROMEXTEN=0117211900") in new stack -- Executing [s@sub-record-check:21] Set("IAX2/0117211900-1067", "__CALLFILENAME=out-0110509058-0117211900-20140702-222326-1404332606.99") in new stack -- Executing [s@sub-record-check:22] Goto("IAX2/0117211900-1067", "out,1") in new stack -- Goto (sub-record-check,out,1) -- Executing [out@sub-record-check:1] ExecIf("IAX2/0117211900-1067", "1?Set(__REC_POLICY_MODE=never)") in new stack -- Executing [out@sub-record-check:2] GosubIf("IAX2/0117211900-1067", "0?record,1(exten,0110509058,0117211900)") in new stack -- Executing [out@sub-record-check:3] Return("IAX2/0117211900-1067", "") in new stack -- Executing [0110509058@from-internal:5] Macro("IAX2/0117211900-1067", "dialout-trunk,3,110509058,,off") in new stack -- Executing [s@macro-dialout-trunk:1] Set("IAX2/0117211900-1067", "DIAL_TRUNK=3") in new stack -- Executing [s@macro-dialout-trunk:2] GosubIf("IAX2/0117211900-1067", "0?sub-pincheck,s,1()") in new stack -- Executing [s@macro-dialout-trunk:3] GotoIf("IAX2/0117211900-1067", "0?disabletrunk,1") in new stack -- Executing [s@macro-dialout-trunk:4] Set("IAX2/0117211900-1067", "DIAL_NUMBER=110509058") in new stack -- Executing [s@macro-dialout-trunk:5] Set("IAX2/0117211900-1067", "DIAL_TRUNK_OPTIONS=tL(10800000:300000)") in new stack -- Executing [s@macro-dialout-trunk:6] Set("IAX2/0117211900-1067", "OUTBOUND_GROUP=OUT_3") in new stack -- Executing [s@macro-dialout-trunk:7] GotoIf("IAX2/0117211900-1067", "1?nomax") in new stack -- Goto (macro-dialout-trunk,s,9) -- Executing [s@macro-dialout-trunk:9] GotoIf("IAX2/0117211900-1067", "0?skipoutcid") in new stack -- Executing [s@macro-dialout-trunk:10] Set("IAX2/0117211900-1067", "DIAL_TRUNK_OPTIONS=tL(10800000:300000)") in new stack -- Executing [s@macro-dialout-trunk:11] Macro("IAX2/0117211900-1067", "outbound-callerid,3") in new stack -- Executing [s@macro-outbound-callerid:1] ExecIf("IAX2/0117211900-1067", "0?Set(CALLERPRES()=)") in new stack -- Executing [s@macro-outbound-callerid:2] ExecIf("IAX2/0117211900-1067", "0?Set(REALCALLERIDNUM=0117211900)") in new stack -- Executing [s@macro-outbound-callerid:3] GotoIf("IAX2/0117211900-1067", "1?normcid") in new stack -- Goto (macro-outbound-callerid,s,6) -- Executing [s@macro-outbound-callerid:6] Set("IAX2/0117211900-1067", "USEROUTCID="Syrex" <0861179739>") in new stack -- Executing [s@macro-outbound-callerid:7] Set("IAX2/0117211900-1067", "EMERGENCYCID=") in new stack -- Executing [s@macro-outbound-callerid:8] Set("IAX2/0117211900-1067", "TRUNKOUTCID=") in new stack -- Executing [s@macro-outbound-callerid:9] GotoIf("IAX2/0117211900-1067", "1?trunkcid") in new stack -- Goto (macro-outbound-callerid,s,14) -- Executing [s@macro-outbound-callerid:14] ExecIf("IAX2/0117211900-1067", "0?Set(CALLERID(all)=)") in new stack -- Executing [s@macro-outbound-callerid:15] ExecIf("IAX2/0117211900-1067", "1?Set(CALLERID(all)="Syrex" <0861179739>)") in new stack -- Executing [s@macro-outbound-callerid:16] ExecIf("IAX2/0117211900-1067", "0?Set(CALLERID(all)=)") in new stack -- Executing [s@macro-outbound-callerid:17] ExecIf("IAX2/0117211900-1067", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack -- Executing [s@macro-outbound-callerid:18] Set("IAX2/0117211900-1067", "CDR(outbound_cnum)=0861179739") in new stack -- Executing [s@macro-outbound-callerid:19] Set("IAX2/0117211900-1067", "CDR(outbound_cnam)=Syrex") in new stack -- Executing [s@macro-dialout-trunk:12] GosubIf("IAX2/0117211900-1067", "1?sub-flp-3,s,1()") in new stack -- Executing [s@sub-flp-3:1] ExecIf("IAX2/0117211900-1067", "0?Return()") in new stack -- Executing [s@sub-flp-3:2] ExecIf("IAX2/0117211900-1067", "0?Return()") in new stack -- Executing [s@sub-flp-3:3] ExecIf("IAX2/0117211900-1067", "0?Return()") in new stack -- Executing [s@sub-flp-3:4] ExecIf("IAX2/0117211900-1067", "1?Set(TARGET_FLP_3=27110509058)") in new stack -- Executing [s@sub-flp-3:5] GotoIf("IAX2/0117211900-1067", "1?match") in new stack -- Goto (sub-flp-3,s,13) -- Executing [s@sub-flp-3:13] Set("IAX2/0117211900-1067", "DIAL_NUMBER=27110509058") in new stack -- Executing [s@sub-flp-3:14] Return("IAX2/0117211900-1067", "") in new stack -- Executing [s@macro-dialout-trunk:13] Set("IAX2/0117211900-1067", "OUTNUM=27110509058") in new stack -- Executing [s@macro-dialout-trunk:14] Set("IAX2/0117211900-1067", "custom=AMP") in new stack -- Executing [s@macro-dialout-trunk:15] ExecIf("IAX2/0117211900-1067", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)tL(10800000:300000))") in new stack -- Executing [s@macro-dialout-trunk:16] ExecIf("IAX2/0117211900-1067", "0?Set(DIAL_TRUNK_OPTIONS=tL(10800000:300000)M(confirm))") in new stack -- Executing [s@macro-dialout-trunk:17] Macro("IAX2/0117211900-1067", "dialout-trunk-predial-hook,") in new stack -- Executing [s@macro-dialout-trunk-predial-hook:1] NoOp("IAX2/0117211900-1067", "Evaluating Channel for possible accountcode override: IAX2/0117211900-1067") in new stack -- Executing [s@macro-dialout-trunk-predial-hook:2] Set("IAX2/0117211900-1067", "CDR(accountcode)=5886269211") in new stack -- Executing [s@macro-dialout-trunk-predial-hook:3] Set("IAX2/0117211900-1067", "OUTNUM=27110509058") in new stack [2014-07-02 22:23:26] WARNING[24965][C-00000031]: chan_sip.c:22046 func_header_read: This function can only be used on SIP channels. [2014-07-02 22:23:26] WARNING[24965][C-00000031]: chan_sip.c:22046 func_header_read: This function can only be used on SIP channels. -- Executing [s@macro-dialout-trunk-predial-hook:4] Set("IAX2/0117211900-1067", "CALLERID(all)='"Syrex" <0861179739>'") in new stack -- Executing [s@macro-dialout-trunk-predial-hook:5] Set("IAX2/0117211900-1067", "CALLERID(all)='Syrex <0861179739>'") in new stack -- Executing [s@macro-dialout-trunk-predial-hook:6] GotoIf("IAX2/0117211900-1067", "1?skip") in new stack -- Goto (macro-dialout-trunk-predial-hook,s,8) -- Executing [s@macro-dialout-trunk-predial-hook:8] GotoIf("IAX2/0117211900-1067", "1?custom-freepbx-a2billing,27110509058,1:2") in new stack -- Goto (custom-freepbx-a2billing,27110509058,1) == Channel 'IAX2/0117211900-1067' jumping out of macro 'dialout-trunk-predial-hook' == Channel 'IAX2/0117211900-1067' jumping out of macro 'dialout-trunk' -- Executing [27110509058@custom-freepbx-a2billing:1] DeadAGI("IAX2/0117211900-1067", "a2billing.php,1") in new stack [2014-07-02 22:23:26] WARNING[24965][C-00000031]: res_agi.c:4005 deadagi_exec: DeadAGI has been deprecated, please use AGI in all cases! -- Launched AGI Script /var/lib/asterisk/agi-bin/a2billing.php Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 00014ms SCall: 28444 DCall: 01067 [196.15.189.26:4569] Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER Timestamp: 00017ms SCall: 01067 DCall: 28444 [196.15.189.26:4569] Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: (255?) Timestamp: 00020ms SCall: 01067 DCall: 28444 [196.15.189.26:4569] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00017ms SCall: 28444 DCall: 01067 [196.15.189.26:4569] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: IAX Subclass: ACK Timestamp: 00020ms SCall: 28444 DCall: 01067 [196.15.189.26:4569] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 004 Type: VOICE Subclass: 136 Timestamp: 00234ms SCall: 28444 DCall: 01067 [196.15.189.26:4569] Tx-Frame Retry[-01] -- OSeqno: 004 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00234ms SCall: 01067 DCall: 28444 [196.15.189.26:4569] -- AGI Script Executing Application: (DIAL) Options: (SIP/ECN/0110509058,60,HRL(36000000:61000:30000)) > Limit Data for this call: > timelimit = 36000000 ms (36000.000 s) > play_warning = 61000 ms (61.000 s) > play_to_caller = yes > play_to_callee = no > warning_freq = 30000 ms (30.000 s) > start_sound = > warning_sound = timeleft > end_sound = == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 Audio is at 10446 Adding codec 100008 (g729) to SDP Adding codec 100004 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (NAT) to 14.122.0.33:5060: INVITE sip:0110509058@14.122.0.33 SIP/2.0 Via: SIP/2.0/UDP 192.25.69.236:5060;branch=z9hG4bK350e762e;rport Max-Forwards: 70 From: "'Syrex" <sip:0861179739@syrex.co.za>;tag=as4dd7c524 To: <sip:0110509058@14.122.0.33> Contact: <sip:0861179739@192.25.69.236:5060> Call-ID: 7249afdb7a50a6d722d5ab386236fd0c@syrex.co.za CSeq: 102 INVITE User-Agent: FPBX-2.11.0(11.9.0) Date: Wed, 02 Jul 2014 20:23:27 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Remote-Party-ID: "'Syrex" <sip:0861179739@syrex.co.za>;party=calling;privacy=off;screen=yes Content-Type: application/sdp Content-Length: 284 v=0 o=root 1523970257 1523970257 IN IP4 192.25.69.236 s=Asterisk PBX 11.9.0 c=IN IP4 192.25.69.236 t=0 0 m=audio 10446 RTP/AVP 18 8 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- -- Called SIP/ECN/0110509058 <--- SIP read from UDP:14.122.0.33:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.25.69.236:5060;received=192.25.69.236;branch=z9hG4bK350e762e;rport=5060 From: "'Syrex" <sip:0861179739@syrex.co.za>;tag=as4dd7c524 To: <sip:0110509058@14.122.0.33>;tag=c97b4d1cb1f3d0da549e06a8d482ef63.30f4 Call-ID: 7249afdb7a50a6d722d5ab386236fd0c@syrex.co.za CSeq: 102 INVITE Proxy-Authenticate: Digest realm="syrex.co.za", nonce="53b46a5d000151dfb2cad7d4224b02cb3f50bd1f23ac882b" Server: OpenSIPS (1.8.3-notls (x86_64/linux)) Content-Length: 0 <-------------> --- (9 headers 0 lines) --- Transmitting (NAT) to 14.122.0.33:5060: ACK sip:0110509058@14.122.0.33 SIP/2.0 Via: SIP/2.0/UDP 192.25.69.236:5060;branch=z9hG4bK350e762e;rport Max-Forwards: 70 From: "'Syrex" <sip:0861179739@syrex.co.za>;tag=as4dd7c524 To: <sip:0110509058@14.122.0.33>;tag=c97b4d1cb1f3d0da549e06a8d482ef63.30f4 Contact: <sip:0861179739@192.25.69.236:5060> Call-ID: 7249afdb7a50a6d722d5ab386236fd0c@syrex.co.za CSeq: 102 ACK User-Agent: FPBX-2.11.0(11.9.0) Content-Length: 0 --- Audio is at 10446 Adding codec 100008 (g729) to SDP Adding codec 100004 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP Reliably Transmitting (NAT) to 14.122.0.33:5060: INVITE sip:0110509058@14.122.0.33 SIP/2.0 Via: SIP/2.0/UDP 192.25.69.236:5060;branch=z9hG4bK3027d12c;rport Max-Forwards: 70 From: "'Syrex" <sip:0861179739@syrex.co.za>;tag=as4dd7c524 To: <sip:0110509058@14.122.0.33> Contact: <sip:0861179739@192.25.69.236:5060> Call-ID: 7249afdb7a50a6d722d5ab386236fd0c@syrex.co.za CSeq: 103 INVITE User-Agent: FPBX-2.11.0(11.9.0) Proxy-Authorization: Digest username="Syr-Jhb-001", realm="syrex.co.za", algorithm=MD5, uri="sip:0110509058@14.122.0.33", nonce="53b46a5d000151dfb2cad7d4224b02cb3f50bd1f23ac882b", response="8c469887c1de5ee2d960364545248294" Date: Wed, 02 Jul 2014 20:23:27 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Remote-Party-ID: "'Syrex" <sip:0861179739@syrex.co.za>;party=calling;privacy=off;screen=yes Content-Type: application/sdp Content-Length: 284 v=0 o=root 1523970257 1523970258 IN IP4 192.25.69.236 s=Asterisk PBX 11.9.0 c=IN IP4 192.25.69.236 t=0 0 m=audio 10446 RTP/AVP 18 8 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- <--- SIP read from UDP:14.122.0.33:5060 ---> SIP/2.0 100 Giving a try Via: SIP/2.0/UDP 192.25.69.236:5060;received=192.25.69.236;branch=z9hG4bK3027d12c;rport=5060 From: "'Syrex" <sip:0861179739@syrex.co.za>;tag=as4dd7c524 To: <sip:0110509058@14.122.0.33> Call-ID: 7249afdb7a50a6d722d5ab386236fd0c@syrex.co.za CSeq: 103 INVITE Server: OpenSIPS (1.8.3-notls (x86_64/linux)) Content-Length: 0 <-------------> --- (8 headers 0 lines) --- <--- SIP read from UDP:14.122.0.33:5060 ---> SIP/2.0 486 Busy here Via: SIP/2.0/UDP 192.25.69.236:5060;received=192.25.69.236;branch=z9hG4bK3027d12c;rport=5060 From: "'Syrex" <sip:0861179739@syrex.co.za>;tag=as4dd7c524 To: <sip:0110509058@14.122.0.33>;tag=as70559c2a Call-ID: 7249afdb7a50a6d722d5ab386236fd0c@syrex.co.za CSeq: 103 INVITE User-Agent: ECN Megaswitch Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-StartID: 7249afdb7a50a6d722d5ab386236fd0c@syrex.co.za Content-Length: 0 <-------------> --- (11 headers 0 lines) --- -- Got SIP response 486 "Busy here" back from 14.122.0.33:5060 Transmitting (NAT) to 14.122.0.33:5060: ACK sip:0110509058@14.122.0.33 SIP/2.0 Via: SIP/2.0/UDP 192.25.69.236:5060;branch=z9hG4bK3027d12c;rport Max-Forwards: 70 From: "'Syrex" <sip:0861179739@syrex.co.za>;tag=as4dd7c524 To: <sip:0110509058@14.122.0.33>;tag=as70559c2a Contact: <sip:0861179739@192.25.69.236:5060> Call-ID: 7249afdb7a50a6d722d5ab386236fd0c@syrex.co.za CSeq: 103 ACK User-Agent: FPBX-2.11.0(11.9.0) Content-Length: 0 --- -- SIP/ECN-00000031 is busy == Everyone is busy/congested at this time (1:1/0/0) -- AGI Script Executing Application: (Busy) Options: (1) Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 003 Type: CONTROL Subclass: BUSY Timestamp: 01520ms SCall: 01067 DCall: 28444 [196.15.189.26:4569] Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 005 Type: IAX Subclass: ACK Timestamp: 01520ms SCall: 28444 DCall: 01067 [196.15.189.26:4569] Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 005 Type: IAX Subclass: HANGUP Timestamp: 01565ms SCall: 28444 DCall: 01067 [196.15.189.26:4569] CAUSE CODE : 17 Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 004 Type: IAX Subclass: ACK Timestamp: 01565ms SCall: 01067 DCall: 28444 [196.15.189.26:4569] -- <IAX2/0117211900-1067>AGI Script a2billing.php completed, returning 4 == Spawn extension (custom-freepbx-a2billing, 27110509058, 1) exited non-zero on 'IAX2/0117211900-1067' -- Executing [h@custom-freepbx-a2billing:1] NoOp("IAX2/0117211900-1067", "h: Dial status: BUSY Hangup cause: 17") in new stack -- Executing [h@custom-freepbx-a2billing:2] Set("IAX2/0117211900-1067", "RC=17") in new stack -- Executing [h@custom-freepbx-a2billing:3] ExecIf("IAX2/0117211900-1067", "1?Playtones(busy)") in new stack -- Executing [h@custom-freepbx-a2billing:4] ExecIf("IAX2/0117211900-1067", "1?Wait(20)") in new stack == Spawn extension (custom-freepbx-a2billing, h, 4) exited non-zero on 'IAX2/0117211900-1067' -- Hungup 'IAX2/0117211900-1067' Really destroying SIP dialog '7249afdb7a50a6d722d5ab386236fd0c@syrex.co.za' Method: INVITE {noformat} Full SIP & IAX2 debug information from Asterisk B, at the same time: {noformat} <--- SIP read from UDP:192.168.10.53:46522 ---> INVITE sip:0110509058@lair.co.za SIP/2.0 Via: SIP/2.0/UDP 192.168.10.53:46522;branch=z9hG4bK-d8754z-7d6f1d21e60c1f18-1---d8754z-;rport Max-Forwards: 70 Contact: <sip:1904@192.168.10.53:46522> To: "0110509058"<sip:0110509058@lair.co.za> From: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: eyeBeam release 1102u stamp 52344 Content-Length: 316 v=0 o=- 1 2 IN IP4 192.168.10.53 s=CounterPath eyeBeam 1.5 c=IN IP4 192.168.10.53 t=0 0 m=audio 49142 RTP/AVP 107 0 8 18 101 a=alt:1 1 : dSBH9CLT OyXgafm6 192.168.10.53 49142 a=fmtp:18 annexb=yes a=fmtp:101 0-15 a=rtpmap:107 BV32/16000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv <-------------> --- (12 headers 13 lines) --- Sending to 192.168.10.53:46522 (NAT) Sending to 192.168.10.53:46522 (NAT) Using INVITE request as basis request - NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. Found peer '1904' for '1904' from 192.168.10.53:46522 <--- Reliably Transmitting (NAT) to 192.168.10.53:46522 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.10.53:46522;branch=z9hG4bK-d8754z-7d6f1d21e60c1f18-1---d8754z-;received=192.168.10.53;rport=46522 From: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 To: "0110509058"<sip:0110509058@lair.co.za>;tag=as6b328efb Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 1 INVITE Server: FPBX-2.11.0(11.9.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="3a3dd78f" Content-Length: 0 <------------> Scheduling destruction of SIP dialog 'NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI.' in 6400 ms (Method: INVITE) <--- SIP read from UDP:192.168.10.53:46522 ---> ACK sip:0110509058@lair.co.za SIP/2.0 Via: SIP/2.0/UDP 192.168.10.53:46522;branch=z9hG4bK-d8754z-7d6f1d21e60c1f18-1---d8754z-;rport To: "0110509058"<sip:0110509058@lair.co.za>;tag=as6b328efb From: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 1 ACK Content-Length: 0 <-------------> --- (7 headers 0 lines) --- <--- SIP read from UDP:192.168.10.53:46522 ---> INVITE sip:0110509058@lair.co.za SIP/2.0 Via: SIP/2.0/UDP 192.168.10.53:46522;branch=z9hG4bK-d8754z-a528aa6ec5503e6e-1---d8754z-;rport Max-Forwards: 70 Contact: <sip:1904@192.168.10.53:46522> To: "0110509058"<sip:0110509058@lair.co.za> From: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 2 INVITE Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO Content-Type: application/sdp User-Agent: eyeBeam release 1102u stamp 52344 Authorization: Digest username="1904",realm="asterisk",nonce="3a3dd78f",uri="sip:0110509058@lair.co.za",response="c21b31b089c51f8a09c0555ebf6820f4",algorithm=MD5 Content-Length: 316 v=0 o=- 1 2 IN IP4 192.168.10.53 s=CounterPath eyeBeam 1.5 c=IN IP4 192.168.10.53 t=0 0 m=audio 49142 RTP/AVP 107 0 8 18 101 a=alt:1 1 : dSBH9CLT OyXgafm6 192.168.10.53 49142 a=fmtp:18 annexb=yes a=fmtp:101 0-15 a=rtpmap:107 BV32/16000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=sendrecv <-------------> --- (13 headers 13 lines) --- Sending to 192.168.10.53:46522 (NAT) Using INVITE request as basis request - NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. Found peer '1904' for '1904' from 192.168.10.53:46522 == Using SIP VIDEO TOS bits 136 == Using SIP VIDEO CoS mark 6 == Using SIP RTP TOS bits 184 == Using SIP RTP CoS mark 5 Found RTP audio format 107 Found RTP audio format 0 Found RTP audio format 8 Found RTP audio format 18 Found RTP audio format 101 Found unknown media description format BV32 for ID 107 Found audio description format G729 for ID 18 Found audio description format telephone-event for ID 101 Capabilities: us - (g723|gsm|ulaw|alaw|g726|adpcm|slin|lpc10|g729|speex|ilbc|g726aal2|g722|h261|h263|h263p|h264), peer - audio=(ulaw|alaw|g729)/video=(nothing)/text=(nothing), combined - (ulaw|alaw|g729) Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) Peer audio RTP is at port 192.168.10.53:49142 Peer doesn't provide video Looking for 0110509058 in from-internal (domain lair.co.za) == Extension Changed 1904[ext-local] new state InUse for Notify User 1964 list_route: hop: <sip:1904@192.168.10.53:46522> <--- Transmitting (NAT) to 192.168.10.53:46522 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.10.53:46522;branch=z9hG4bK-d8754z-a528aa6ec5503e6e-1---d8754z-;received=192.168.10.53;rport=46522 From: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 To: "0110509058"<sip:0110509058@lair.co.za> Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 2 INVITE Server: FPBX-2.11.0(11.9.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: <sip:0110509058@192.168.1.11:5060> Content-Length: 0 <------------> == Extension Changed 1904[ext-local] new state InUse for Notify User 1900 -- Executing [0110509058@from-internal:1] Macro("SIP/1904-0000a921", "user-callerid,LIMIT,EXTERNAL,") in new stack -- Executing [s@macro-user-callerid:1] Set("SIP/1904-0000a921", "TOUCH_MONITOR=1404332606.93170") in new stack -- Executing [s@macro-user-callerid:2] Set("SIP/1904-0000a921", "AMPUSER=1904") in new stack -- Executing [s@macro-user-callerid:3] GotoIf("SIP/1904-0000a921", "0?report") in new stack -- Executing [s@macro-user-callerid:4] ExecIf("SIP/1904-0000a921", "1?Set(REALCALLERIDNUM=1904)") in new stack -- Executing [s@macro-user-callerid:5] Set("SIP/1904-0000a921", "AMPUSER=1904") in new stack -- Executing [s@macro-user-callerid:6] GotoIf("SIP/1904-0000a921", "0?limit") in new stack -- Executing [s@macro-user-callerid:7] Set("SIP/1904-0000a921", "AMPUSERCIDNAME=David Herselman") in new stack -- Executing [s@macro-user-callerid:8] GotoIf("SIP/1904-0000a921", "0?report") in new stack -- Executing [s@macro-user-callerid:9] Set("SIP/1904-0000a921", "AMPUSERCID=1904") in new stack -- Executing [s@macro-user-callerid:10] Set("SIP/1904-0000a921", "__DIAL_OPTIONS=trL(10800000:300000)") in new stack -- Executing [s@macro-user-callerid:11] Set("SIP/1904-0000a921", "CALLERID(all)="David Herselman" <1904>") in new stack -- Executing [s@macro-user-callerid:12] GotoIf("SIP/1904-0000a921", "0?limit") in new stack -- Executing [s@macro-user-callerid:13] ExecIf("SIP/1904-0000a921", "1?Set(GROUP(concurrency_limit)=1904)") in new stack -- Executing [s@macro-user-callerid:14] GosubIf("SIP/1904-0000a921", "7?sub-ccss,s,1(from-internal,0110509058)") in new stack -- Executing [s@sub-ccss:1] ExecIf("SIP/1904-0000a921", "0?Return()") in new stack -- Executing [s@sub-ccss:2] Set("SIP/1904-0000a921", "CCSS_SETUP=TRUE") in new stack -- Executing [s@sub-ccss:3] GosubIf("SIP/1904-0000a921", "0?monitor_config,1(from-internal,0110509058):monitor_default,1(from-internal,0110509058)") in new stack -- Executing [monitor_default@sub-ccss:1] GotoIf("SIP/1904-0000a921", "0?is_exten") in new stack -- Executing [monitor_default@sub-ccss:2] StackPop("SIP/1904-0000a921", "") in new stack -- Executing [monitor_default@sub-ccss:3] Return("SIP/1904-0000a921", "FALSE") in new stack -- Executing [s@macro-user-callerid:15] ExecIf("SIP/1904-0000a921", "0?Set(CHANNEL(language)=)") in new stack -- Executing [s@macro-user-callerid:16] GotoIf("SIP/1904-0000a921", "1?continue") in new stack -- Goto (macro-user-callerid,s,30) -- Executing [s@macro-user-callerid:30] Set("SIP/1904-0000a921", "CALLERID(number)=1904") in new stack -- Executing [s@macro-user-callerid:31] Set("SIP/1904-0000a921", "CALLERID(name)=David Herselman") in new stack -- Executing [s@macro-user-callerid:32] Set("SIP/1904-0000a921", "CDR(cnum)=1904") in new stack -- Executing [s@macro-user-callerid:33] Set("SIP/1904-0000a921", "CDR(cnam)=David Herselman") in new stack -- Executing [s@macro-user-callerid:34] Set("SIP/1904-0000a921", "CHANNEL(language)=en") in new stack -- Executing [0110509058@from-internal:2] ExecIf("SIP/1904-0000a921", "0 ?Set(CDR(accountcode)=)") in new stack -- Executing [0110509058@from-internal:3] Set("SIP/1904-0000a921", "MOHCLASS=default") in new stack -- Executing [0110509058@from-internal:4] Set("SIP/1904-0000a921", "_NODEST=") in new stack -- Executing [0110509058@from-internal:5] Gosub("SIP/1904-0000a921", "sub-record-check,s,1(out,0110509058,)") in new stack -- Executing [s@sub-record-check:1] Set("SIP/1904-0000a921", "REC_POLICY_MODE_SAVE=") in new stack -- Executing [s@sub-record-check:2] GotoIf("SIP/1904-0000a921", "1?check") in new stack -- Goto (sub-record-check,s,7) -- Executing [s@sub-record-check:7] Set("SIP/1904-0000a921", "__MON_FMT=wav") in new stack -- Executing [s@sub-record-check:8] GotoIf("SIP/1904-0000a921", "1?next") in new stack -- Goto (sub-record-check,s,11) -- Executing [s@sub-record-check:11] ExecIf("SIP/1904-0000a921", "0?Return()") in new stack -- Executing [s@sub-record-check:12] ExecIf("SIP/1904-0000a921", "0?Set(__REC_POLICY_MODE=)") in new stack -- Executing [s@sub-record-check:13] GotoIf("SIP/1904-0000a921", "0?out,1") in new stack -- Executing [s@sub-record-check:14] Set("SIP/1904-0000a921", "__REC_STATUS=INITIALIZED") in new stack -- Executing [s@sub-record-check:15] Set("SIP/1904-0000a921", "NOW=1404332606") in new stack -- Executing [s@sub-record-check:16] Set("SIP/1904-0000a921", "__DAY=02") in new stack -- Executing [s@sub-record-check:17] Set("SIP/1904-0000a921", "__MONTH=07") in new stack -- Executing [s@sub-record-check:18] Set("SIP/1904-0000a921", "__YEAR=2014") in new stack -- Executing [s@sub-record-check:19] Set("SIP/1904-0000a921", "__TIMESTR=20140702-222326") in new stack -- Executing [s@sub-record-check:20] Set("SIP/1904-0000a921", "__FROMEXTEN=1904") in new stack -- Executing [s@sub-record-check:21] Set("SIP/1904-0000a921", "__CALLFILENAME=out-0110509058-1904-20140702-222326-1404332606.93170") in new stack -- Executing [s@sub-record-check:22] Goto("SIP/1904-0000a921", "out,1") in new stack -- Goto (sub-record-check,out,1) -- Executing [out@sub-record-check:1] ExecIf("SIP/1904-0000a921", "1?Set(__REC_POLICY_MODE=always)") in new stack -- Executing [out@sub-record-check:2] GosubIf("SIP/1904-0000a921", "1?record,1(exten,0110509058,1904)") in new stack -- Executing [record@sub-record-check:1] Set("SIP/1904-0000a921", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack -- Executing [record@sub-record-check:2] MixMonitor("SIP/1904-0000a921", "2014/07/02/out-0110509058-1904-20140702-222326-1404332606.93170.wav,,") in new stack -- Executing [record@sub-record-check:3] Set("SIP/1904-0000a921", "__REC_STATUS=RECORDING") in new stack -- Executing [record@sub-record-check:4] Set("SIP/1904-0000a921", "CDR(recordingfile)=out-0110509058-1904-20140702-222326-1404332606.93170.wav") in new stack -- Executing [record@sub-record-check:5] Return("SIP/1904-0000a921", "") in new stack -- Executing [out@sub-record-check:3] Return("SIP/1904-0000a921", "") in new stack == Begin MixMonitor Recording SIP/1904-0000a921 -- Executing [0110509058@from-internal:6] Macro("SIP/1904-0000a921", "dialout-trunk,7,110509058,,off") in new stack -- Executing [s@macro-dialout-trunk:1] Set("SIP/1904-0000a921", "DIAL_TRUNK=7") in new stack -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/1904-0000a921", "0?sub-pincheck,s,1()") in new stack -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/1904-0000a921", "0?disabletrunk,1") in new stack -- Executing [s@macro-dialout-trunk:4] Set("SIP/1904-0000a921", "DIAL_NUMBER=110509058") in new stack -- Executing [s@macro-dialout-trunk:5] Set("SIP/1904-0000a921", "DIAL_TRUNK_OPTIONS=trL(10800000:300000)") in new stack -- Executing [s@macro-dialout-trunk:6] Set("SIP/1904-0000a921", "OUTBOUND_GROUP=OUT_7") in new stack -- Executing [s@macro-dialout-trunk:7] GotoIf("SIP/1904-0000a921", "1?nomax") in new stack -- Goto (macro-dialout-trunk,s,9) -- Executing [s@macro-dialout-trunk:9] GotoIf("SIP/1904-0000a921", "0?skipoutcid") in new stack -- Executing [s@macro-dialout-trunk:10] Set("SIP/1904-0000a921", "DIAL_TRUNK_OPTIONS=tL(10800000:300000)") in new stack -- Executing [s@macro-dialout-trunk:11] Macro("SIP/1904-0000a921", "outbound-callerid,7") in new stack -- Executing [s@macro-outbound-callerid:1] ExecIf("SIP/1904-0000a921", "0?Set(CALLERPRES()=)") in new stack -- Executing [s@macro-outbound-callerid:2] ExecIf("SIP/1904-0000a921", "0?Set(REALCALLERIDNUM=1904)") in new stack -- Executing [s@macro-outbound-callerid:3] GotoIf("SIP/1904-0000a921", "1?normcid") in new stack -- Goto (macro-outbound-callerid,s,6) -- Executing [s@macro-outbound-callerid:6] Set("SIP/1904-0000a921", "USEROUTCID=") in new stack -- Executing [s@macro-outbound-callerid:7] Set("SIP/1904-0000a921", "EMERGENCYCID=") in new stack -- Executing [s@macro-outbound-callerid:8] Set("SIP/1904-0000a921", "TRUNKOUTCID="Syrex" <0861179739>") in new stack -- Executing [s@macro-outbound-callerid:9] GotoIf("SIP/1904-0000a921", "1?trunkcid") in new stack -- Goto (macro-outbound-callerid,s,14) -- Executing [s@macro-outbound-callerid:14] ExecIf("SIP/1904-0000a921", "1?Set(CALLERID(all)="Syrex" <0861179739>)") in new stack -- Executing [s@macro-outbound-callerid:15] ExecIf("SIP/1904-0000a921", "0?Set(CALLERID(all)=)") in new stack -- Executing [s@macro-outbound-callerid:16] ExecIf("SIP/1904-0000a921", "0?Set(CALLERID(all)=)") in new stack -- Executing [s@macro-outbound-callerid:17] ExecIf("SIP/1904-0000a921", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack -- Executing [s@macro-outbound-callerid:18] Set("SIP/1904-0000a921", "CDR(outbound_cnum)=0861179739") in new stack -- Executing [s@macro-outbound-callerid:19] Set("SIP/1904-0000a921", "CDR(outbound_cnam)=Syrex") in new stack -- Executing [s@macro-dialout-trunk:12] GosubIf("SIP/1904-0000a921", "1?sub-flp-7,s,1()") in new stack -- Executing [s@sub-flp-7:1] ExecIf("SIP/1904-0000a921", "0?Return()") in new stack -- Executing [s@sub-flp-7:2] ExecIf("SIP/1904-0000a921", "0?Return()") in new stack -- Executing [s@sub-flp-7:3] ExecIf("SIP/1904-0000a921", "0?Return()") in new stack -- Executing [s@sub-flp-7:4] ExecIf("SIP/1904-0000a921", "1?Set(TARGET_FLP_7=0110509058)") in new stack -- Executing [s@sub-flp-7:5] GotoIf("SIP/1904-0000a921", "1?match") in new stack -- Goto (sub-flp-7,s,15) -- Executing [s@sub-flp-7:15] Set("SIP/1904-0000a921", "DIAL_NUMBER=0110509058") in new stack -- Executing [s@sub-flp-7:16] Return("SIP/1904-0000a921", "") in new stack -- Executing [s@macro-dialout-trunk:13] Set("SIP/1904-0000a921", "OUTNUM=0110509058") in new stack -- Executing [s@macro-dialout-trunk:14] Set("SIP/1904-0000a921", "custom=IAX2/Syrex") in new stack -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/1904-0000a921", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)tL(10800000:300000))") in new stack -- Executing [s@macro-dialout-trunk:16] ExecIf("SIP/1904-0000a921", "0?Set(DIAL_TRUNK_OPTIONS=tL(10800000:300000)M(confirm))") in new stack -- Executing [s@macro-dialout-trunk:17] Macro("SIP/1904-0000a921", "dialout-trunk-predial-hook,") in new stack -- Executing [s@macro-dialout-trunk-predial-hook:1] Set("SIP/1904-0000a921", "CALLERID(num)=0861179739") in new stack -- Executing [s@macro-dialout-trunk-predial-hook:2] SIPAddHeader("SIP/1904-0000a921", "X-CallerID:"Syrex" <0861179739>") in new stack -- Executing [s@macro-dialout-trunk-predial-hook:3] Set("SIP/1904-0000a921", "IAXVAR(X-CallerID)="Syrex" <0861179739>") in new stack -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/1904-0000a921", "0?bypass,1") in new stack -- Executing [s@macro-dialout-trunk:19] ExecIf("SIP/1904-0000a921", "1?Set(CONNECTEDLINE(num,i)=0110509058)") in new stack -- Executing [s@macro-dialout-trunk:20] ExecIf("SIP/1904-0000a921", "1?Set(CONNECTEDLINE(name,i)=CID:0861179739)") in new stack -- Executing [s@macro-dialout-trunk:21] GotoIf("SIP/1904-0000a921", "0?customtrunk") in new stack -- Executing [s@macro-dialout-trunk:22] Dial("SIP/1904-0000a921", "IAX2/Syrex/0110509058,300,tL(10800000:300000)") in new stack > Limit Data for this call: > timelimit = 10800000 ms (10800.000 s) > play_warning = 300000 ms (300.000 s) > play_to_caller = yes > play_to_callee = no > warning_freq = 0 ms (0.000 s) > start_sound = > warning_sound = timeleft > end_sound = -- Called IAX2/Syrex/0110509058 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00010ms SCall: 28444 DCall: 00000 [192.25.69.236:4569] VERSION : 2 CALLED NUMBER : 0110509058 CODEC_PREFS : (g729) CALLING NUMBER : 0861179739 CALLING PRESNTN : 0 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : Syrex LANGUAGE : en USERNAME : 0117211900 FORMAT : 256 FORMAT2 : g729 CAPABILITY : 256 CAPABILITY2 : g729 ADSICPE : 2 DATE TIME : 2014-07-02 22:23:26 VARIABLE : X-CallerID="Syrex" <0861179739> Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN Timestamp: 00010ms SCall: 00001 DCall: 28444 [192.25.69.236:4569] CALLTOKEN : 51 bytes Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW Timestamp: 00019ms SCall: 28444 DCall: 00000 [192.25.69.236:4569] VERSION : 2 CALLED NUMBER : 0110509058 CODEC_PREFS : (g729) CALLING NUMBER : 0861179739 CALLING PRESNTN : 0 CALLING TYPEOFN : 0 CALLING TRANSIT : 0 CALLING NAME : Syrex LANGUAGE : en USERNAME : 0117211900 FORMAT : 256 FORMAT2 : g729 CAPABILITY : 256 CAPABILITY2 : g729 ADSICPE : 2 DATE TIME : 2014-07-02 22:23:26 VARIABLE : X-CallerID="Syrex" <0861179739> CALLTOKEN : 51 bytes Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: AUTHREQ Timestamp: 00006ms SCall: 01067 DCall: 28444 [192.25.69.236:4569] AUTHMETHODS : 3 CHALLENGE : \x32\x31\x30\x37\x36\x38\x32\x37\x32 USERNAME : 0117211900 Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: AUTHREP Timestamp: 00029ms SCall: 28444 DCall: 01067 [192.25.69.236:4569] MD5 RESULT : 51a97d41d350ef6698fb7f07ec832a9f Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACCEPT Timestamp: 00014ms SCall: 01067 DCall: 28444 [192.25.69.236:4569] FORMAT : 256 FORMAT2 : g729 -- Call accepted by 192.25.69.236 (format g729) -- Format for call is (g729) Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK Timestamp: 00014ms SCall: 28444 DCall: 01067 [192.25.69.236:4569] Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER Timestamp: 00017ms SCall: 01067 DCall: 28444 [192.25.69.236:4569] Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00017ms SCall: 28444 DCall: 01067 [192.25.69.236:4569] Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: (255?) Timestamp: 00020ms SCall: 01067 DCall: 28444 [192.25.69.236:4569] Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 004 Type: IAX Subclass: ACK Timestamp: 00020ms SCall: 28444 DCall: 01067 [192.25.69.236:4569] -- IAX2/Syrex-28444 answered SIP/1904-0000a921 Audio is at 13046 Adding codec 100004 (alaw) to SDP Adding codec 100003 (ulaw) to SDP Adding codec 100008 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP <--- Reliably Transmitting (NAT) to 192.168.10.53:46522 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.10.53:46522;branch=z9hG4bK-d8754z-a528aa6ec5503e6e-1---d8754z-;received=192.168.10.53;rport=46522 From: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 To: "0110509058"<sip:0110509058@lair.co.za>;tag=as33aa39e7 Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 2 INVITE Server: FPBX-2.11.0(11.9.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: <sip:0110509058@192.168.1.11:5060> P-Asserted-Identity: "CID:0861179739" <sip:0110509058@lair.co.za> Content-Type: application/sdp Content-Length: 304 v=0 o=root 147972814 147972814 IN IP4 192.168.1.11 s=Asterisk PBX 11.9.0 c=IN IP4 192.168.1.11 t=0 0 m=audio 13046 RTP/AVP 8 0 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <------------> > 0x2b2bf49e36a0 -- Probation passed - setting RTP source address to 192.168.10.53:49142 Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 004 Type: VOICE Subclass: 136 Timestamp: 00234ms SCall: 28444 DCall: 01067 [192.25.69.236:4569] Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 003 Type: IAX Subclass: ACK Timestamp: 00234ms SCall: 01067 DCall: 28444 [192.25.69.236:4569] Retransmitting #1 (NAT) to 192.168.10.53:46522: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.10.53:46522;branch=z9hG4bK-d8754z-a528aa6ec5503e6e-1---d8754z-;received=192.168.10.53;rport=46522 From: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 To: "0110509058"<sip:0110509058@lair.co.za>;tag=as33aa39e7 Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 2 INVITE Server: FPBX-2.11.0(11.9.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE Supported: replaces, timer Contact: <sip:0110509058@192.168.1.11:5060> P-Asserted-Identity: "CID:0861179739" <sip:0110509058@lair.co.za> Content-Type: application/sdp Content-Length: 304 v=0 o=root 147972814 147972814 IN IP4 192.168.1.11 s=Asterisk PBX 11.9.0 c=IN IP4 192.168.1.11 t=0 0 m=audio 13046 RTP/AVP 8 0 18 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- <--- SIP read from UDP:192.168.10.53:46522 ---> ACK sip:0110509058@192.168.1.11:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.10.53:46522;branch=z9hG4bK-d8754z-1b4d7a6e6539e83c-1---d8754z-;rport Max-Forwards: 70 Contact: <sip:1904@192.168.10.53:46522> To: "0110509058"<sip:0110509058@lair.co.za>;tag=as33aa39e7 From: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 2 ACK User-Agent: eyeBeam release 1102u stamp 52344 Authorization: Digest username="1904",realm="asterisk",nonce="3a3dd78f",uri="sip:0110509058@lair.co.za",response="c21b31b089c51f8a09c0555ebf6820f4",algorithm=MD5 Content-Length: 0 <-------------> --- (11 headers 0 lines) --- <--- SIP read from UDP:192.168.10.53:46522 ---> ACK sip:0110509058@192.168.1.11:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.10.53:46522;branch=z9hG4bK-d8754z-1b4d7a6e6539e83c-1---d8754z-;rport Max-Forwards: 70 Contact: <sip:1904@192.168.10.53:46522> To: "0110509058"<sip:0110509058@lair.co.za>;tag=as33aa39e7 From: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 2 ACK User-Agent: eyeBeam release 1102u stamp 52344 Authorization: Digest username="1904",realm="asterisk",nonce="3a3dd78f",uri="sip:0110509058@lair.co.za",response="c21b31b089c51f8a09c0555ebf6820f4",algorithm=MD5 Content-Length: 0 <-------------> --- (11 headers 0 lines) --- Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 003 Type: CONTROL Subclass: BUSY Timestamp: 01520ms SCall: 01067 DCall: 28444 [192.25.69.236:4569] Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 005 Type: IAX Subclass: ACK Timestamp: 01520ms SCall: 28444 DCall: 01067 [192.25.69.236:4569] -- Executing [h@macro-dialout-trunk:1] Macro("SIP/1904-0000a921", "hangupcall,") in new stack -- Executing [s@macro-hangupcall:1] GotoIf("SIP/1904-0000a921", "1?theend") in new stack -- Goto (macro-hangupcall,s,3) -- Executing [s@macro-hangupcall:3] ExecIf("SIP/1904-0000a921", "0?Set(CDR(recordingfile)=)") in new stack -- Executing [s@macro-hangupcall:4] Hangup("SIP/1904-0000a921", "") in new stack == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/1904-0000a921' in macro 'hangupcall' == Spawn extension (macro-dialout-trunk, h, 1) exited non-zero on 'SIP/1904-0000a921' -- Hungup 'IAX2/Syrex-28444' Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 005 Type: IAX Subclass: HANGUP Timestamp: 01565ms SCall: 28444 DCall: 01067 [192.25.69.236:4569] CAUSE CODE : 17 == Spawn extension (macro-dialout-trunk, s, 22) exited non-zero on 'SIP/1904-0000a921' in macro 'dialout-trunk' == Spawn extension (from-internal, 0110509058, 6) exited non-zero on 'SIP/1904-0000a921' Scheduling destruction of SIP dialog 'NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI.' in 6400 ms (Method: ACK) set_destination: Parsing <sip:1904@192.168.10.53:46522> for address/port to send to set_destination: set destination to 192.168.10.53:46522 Reliably Transmitting (NAT) to 192.168.10.53:46522: BYE sip:1904@192.168.10.53:46522 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK265cfa61;rport Max-Forwards: 70 From: "0110509058"<sip:0110509058@lair.co.za>;tag=as33aa39e7 To: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 102 BYE User-Agent: FPBX-2.11.0(11.9.0) Proxy-Authorization: Digest username="1904", realm="asterisk", algorithm=MD5, uri="sip:lair.co.za", nonce="3a3dd78f", response="8d29c6eccdbf34a6d2b0ada9b6a83b01" X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- == Extension Changed 1904[ext-local] new state Idle for Notify User 1964 == MixMonitor close filestream (mixed) == End MixMonitor Recording SIP/1904-0000a921 == Extension Changed 1904[ext-local] new state Idle for Notify User 1900 Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 004 Type: IAX Subclass: ACK Timestamp: 01565ms SCall: 01067 DCall: 28444 [192.25.69.236:4569] Retransmitting #1 (NAT) to 192.168.10.53:46522: BYE sip:1904@192.168.10.53:46522 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK265cfa61;rport Max-Forwards: 70 From: "0110509058"<sip:0110509058@lair.co.za>;tag=as33aa39e7 To: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 102 BYE User-Agent: FPBX-2.11.0(11.9.0) Proxy-Authorization: Digest username="1904", realm="asterisk", algorithm=MD5, uri="sip:lair.co.za", nonce="3a3dd78f", response="8d29c6eccdbf34a6d2b0ada9b6a83b01" X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 --- <--- SIP read from UDP:192.168.10.53:46522 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK265cfa61;rport=5060 Contact: <sip:1904@192.168.10.53:46522> To: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 From: "0110509058"<sip:0110509058@lair.co.za>;tag=as33aa39e7 Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 102 BYE User-Agent: eyeBeam release 1102u stamp 52344 Content-Length: 0 <-------------> --- (9 headers 0 lines) --- SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog 'NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI.' Method: ACK <--- SIP read from UDP:192.168.10.53:46522 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.11:5060;branch=z9hG4bK265cfa61;rport=5060 Contact: <sip:1904@192.168.10.53:46522> To: "David Herselman"<sip:1904@lair.co.za>;tag=7e5f7034 From: "0110509058"<sip:0110509058@lair.co.za>;tag=as33aa39e7 Call-ID: NDNjZWU5NmEzMTA1YTRhOWJkOTUzNjVlNDE1ODJlNDI. CSeq: 102 BYE User-Agent: eyeBeam release 1102u stamp 52344 Content-Length: 0 <-------------> --- (9 headers 0 lines) --- {noformat} By: David Herselman (bbs2web) 2014-07-03 05:21:43.261-0500 The issue here was Asterisk A answering the call prior to initiating the outbound call to the upstream SIP provider. This strangely however works when the trunk between Asterisk A and Asterisk B utilities SIP. Issue traced to A2Billing on Asterisk A (we account for billing between our branches) which had 'agi-conf1' set to answer the call. My apologies to anyone who wasted time on this! By: Rusty Newton (rnewton) 2014-07-09 15:51:52.460-0500 I'm glad you figured it out. I probably would have ended up closing it out due to the complexity of reproducing it. We generally require that the reporter have it pretty narrowed down, otherwise it is difficult to move forward. No worries! | ||||