[asterisk-bugs] [JIRA] (ASTERISK-23979) IAX2 trunk dial status and hangup cause not sent to SIP endpoint

David Herselman (JIRA) noreply at issues.asterisk.org
Wed Jul 2 15:49:56 CDT 2014


    [ https://issues.asterisk.org/jira/browse/ASTERISK-23979?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=220211#comment-220211 ] 

David Herselman commented on ASTERISK-23979:
--------------------------------------------

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 at from-internal:1] Macro("IAX2/0117211900-1067", "user-callerid,LIMIT,EXTERNAL,") in new stack
    -- Executing [s at macro-user-callerid:1] Set("IAX2/0117211900-1067", "TOUCH_MONITOR=1404332606.99") in new stack
    -- Executing [s at macro-user-callerid:2] Set("IAX2/0117211900-1067", "AMPUSER=0117211900") in new stack
    -- Executing [s at macro-user-callerid:3] GotoIf("IAX2/0117211900-1067", "0?report") in new stack
    -- Executing [s at macro-user-callerid:4] ExecIf("IAX2/0117211900-1067", "0?Set(REALCALLERIDNUM=0117211900)") in new stack
    -- Executing [s at macro-user-callerid:5] Set("IAX2/0117211900-1067", "AMPUSER=0117211900") in new stack
    -- Executing [s at macro-user-callerid:6] GotoIf("IAX2/0117211900-1067", "0?limit") in new stack
    -- Executing [s at macro-user-callerid:7] Set("IAX2/0117211900-1067", "AMPUSERCIDNAME=Syrex") in new stack
    -- Executing [s at macro-user-callerid:8] GotoIf("IAX2/0117211900-1067", "0?report") in new stack
    -- Executing [s at macro-user-callerid:9] Set("IAX2/0117211900-1067", "AMPUSERCID=0117211900") in new stack
    -- Executing [s at macro-user-callerid:10] Set("IAX2/0117211900-1067", "__DIAL_OPTIONS=tL(10800000:300000)") in new stack
    -- Executing [s at macro-user-callerid:11] Set("IAX2/0117211900-1067", "CALLERID(all)="Syrex" <0117211900>") in new stack
    -- Executing [s at macro-user-callerid:12] GotoIf("IAX2/0117211900-1067", "0?limit") in new stack
    -- Executing [s at macro-user-callerid:13] ExecIf("IAX2/0117211900-1067", "1?Set(GROUP(concurrency_limit)=0117211900)") in new stack
    -- Executing [s at macro-user-callerid:14] ExecIf("IAX2/0117211900-1067", "0?Set(CHANNEL(language)=)") in new stack
    -- Executing [s at macro-user-callerid:15] GosubIf("IAX2/0117211900-1067", "7?sub-ccss,s,1(from-internal,)") in new stack
    -- Executing [s at sub-ccss:1] ExecIf("IAX2/0117211900-1067", "0?Return()") in new stack
    -- Executing [s at sub-ccss:2] Set("IAX2/0117211900-1067", "CCSS_SETUP=TRUE") in new stack
    -- Executing [s at sub-ccss:3] GosubIf("IAX2/0117211900-1067", "0?monitor_config,1(from-internal,):monitor_default,1(from-internal,)") in new stack
    -- Executing [monitor_default at sub-ccss:1] GotoIf("IAX2/0117211900-1067", "0?is_exten") in new stack
    -- Executing [monitor_default at sub-ccss:2] StackPop("IAX2/0117211900-1067", "") in new stack
    -- Executing [monitor_default at sub-ccss:3] Return("IAX2/0117211900-1067", "FALSE") in new stack
    -- Executing [s at macro-user-callerid:16] GotoIf("IAX2/0117211900-1067", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,29)
    -- Executing [s at macro-user-callerid:29] Set("IAX2/0117211900-1067", "CALLERID(number)=0117211900") in new stack
    -- Executing [s at macro-user-callerid:30] Set("IAX2/0117211900-1067", "CALLERID(name)=Syrex") in new stack
    -- Executing [s at macro-user-callerid:31] Set("IAX2/0117211900-1067", "CDR(cnum)=0117211900") in new stack
    -- Executing [s at macro-user-callerid:32] Set("IAX2/0117211900-1067", "CDR(cnam)=Syrex") in new stack
    -- Executing [s at macro-user-callerid:33] Set("IAX2/0117211900-1067", "CHANNEL(language)=en") in new stack
    -- Executing [0110509058 at from-internal:2] Set("IAX2/0117211900-1067", "MOHCLASS=default") in new stack
    -- Executing [0110509058 at from-internal:3] Set("IAX2/0117211900-1067", "_NODEST=") in new stack
    -- Executing [0110509058 at from-internal:4] Gosub("IAX2/0117211900-1067", "sub-record-check,s,1(out,0110509058,)") in new stack
    -- Executing [s at sub-record-check:1] Set("IAX2/0117211900-1067", "REC_POLICY_MODE_SAVE=") in new stack
    -- Executing [s at sub-record-check:2] GotoIf("IAX2/0117211900-1067", "1?check") in new stack
    -- Goto (sub-record-check,s,7)
    -- Executing [s at sub-record-check:7] Set("IAX2/0117211900-1067", "__MON_FMT=wav") in new stack
    -- Executing [s at sub-record-check:8] GotoIf("IAX2/0117211900-1067", "1?next") in new stack
    -- Goto (sub-record-check,s,11)
    -- Executing [s at sub-record-check:11] ExecIf("IAX2/0117211900-1067", "0?Return()") in new stack
    -- Executing [s at sub-record-check:12] ExecIf("IAX2/0117211900-1067", "0?Set(__REC_POLICY_MODE=)") in new stack
    -- Executing [s at sub-record-check:13] GotoIf("IAX2/0117211900-1067", "0?out,1") in new stack
    -- Executing [s at sub-record-check:14] Set("IAX2/0117211900-1067", "__REC_STATUS=INITIALIZED") in new stack
    -- Executing [s at sub-record-check:15] Set("IAX2/0117211900-1067", "NOW=1404332606") in new stack
    -- Executing [s at sub-record-check:16] Set("IAX2/0117211900-1067", "__DAY=02") in new stack
    -- Executing [s at sub-record-check:17] Set("IAX2/0117211900-1067", "__MONTH=07") in new stack
    -- Executing [s at sub-record-check:18] Set("IAX2/0117211900-1067", "__YEAR=2014") in new stack
    -- Executing [s at sub-record-check:19] Set("IAX2/0117211900-1067", "__TIMESTR=20140702-222326") in new stack
    -- Executing [s at sub-record-check:20] Set("IAX2/0117211900-1067", "__FROMEXTEN=0117211900") in new stack
    -- Executing [s at sub-record-check:21] Set("IAX2/0117211900-1067", "__CALLFILENAME=out-0110509058-0117211900-20140702-222326-1404332606.99") in new stack
    -- Executing [s at sub-record-check:22] Goto("IAX2/0117211900-1067", "out,1") in new stack
    -- Goto (sub-record-check,out,1)
    -- Executing [out at sub-record-check:1] ExecIf("IAX2/0117211900-1067", "1?Set(__REC_POLICY_MODE=never)") in new stack
    -- Executing [out at sub-record-check:2] GosubIf("IAX2/0117211900-1067", "0?record,1(exten,0110509058,0117211900)") in new stack
    -- Executing [out at sub-record-check:3] Return("IAX2/0117211900-1067", "") in new stack
    -- Executing [0110509058 at from-internal:5] Macro("IAX2/0117211900-1067", "dialout-trunk,3,110509058,,off") in new stack
    -- Executing [s at macro-dialout-trunk:1] Set("IAX2/0117211900-1067", "DIAL_TRUNK=3") in new stack
    -- Executing [s at macro-dialout-trunk:2] GosubIf("IAX2/0117211900-1067", "0?sub-pincheck,s,1()") in new stack
    -- Executing [s at macro-dialout-trunk:3] GotoIf("IAX2/0117211900-1067", "0?disabletrunk,1") in new stack
    -- Executing [s at macro-dialout-trunk:4] Set("IAX2/0117211900-1067", "DIAL_NUMBER=110509058") in new stack
    -- Executing [s at macro-dialout-trunk:5] Set("IAX2/0117211900-1067", "DIAL_TRUNK_OPTIONS=tL(10800000:300000)") in new stack
    -- Executing [s at macro-dialout-trunk:6] Set("IAX2/0117211900-1067", "OUTBOUND_GROUP=OUT_3") in new stack
    -- Executing [s at macro-dialout-trunk:7] GotoIf("IAX2/0117211900-1067", "1?nomax") in new stack
    -- Goto (macro-dialout-trunk,s,9)
    -- Executing [s at macro-dialout-trunk:9] GotoIf("IAX2/0117211900-1067", "0?skipoutcid") in new stack
    -- Executing [s at macro-dialout-trunk:10] Set("IAX2/0117211900-1067", "DIAL_TRUNK_OPTIONS=tL(10800000:300000)") in new stack
    -- Executing [s at macro-dialout-trunk:11] Macro("IAX2/0117211900-1067", "outbound-callerid,3") in new stack
    -- Executing [s at macro-outbound-callerid:1] ExecIf("IAX2/0117211900-1067", "0?Set(CALLERPRES()=)") in new stack
    -- Executing [s at macro-outbound-callerid:2] ExecIf("IAX2/0117211900-1067", "0?Set(REALCALLERIDNUM=0117211900)") in new stack
    -- Executing [s at macro-outbound-callerid:3] GotoIf("IAX2/0117211900-1067", "1?normcid") in new stack
    -- Goto (macro-outbound-callerid,s,6)
    -- Executing [s at macro-outbound-callerid:6] Set("IAX2/0117211900-1067", "USEROUTCID="Syrex" <0861179739>") in new stack
    -- Executing [s at macro-outbound-callerid:7] Set("IAX2/0117211900-1067", "EMERGENCYCID=") in new stack
    -- Executing [s at macro-outbound-callerid:8] Set("IAX2/0117211900-1067", "TRUNKOUTCID=") in new stack
    -- Executing [s at macro-outbound-callerid:9] GotoIf("IAX2/0117211900-1067", "1?trunkcid") in new stack
    -- Goto (macro-outbound-callerid,s,14)
    -- Executing [s at macro-outbound-callerid:14] ExecIf("IAX2/0117211900-1067", "0?Set(CALLERID(all)=)") in new stack
    -- Executing [s at macro-outbound-callerid:15] ExecIf("IAX2/0117211900-1067", "1?Set(CALLERID(all)="Syrex" <0861179739>)") in new stack
    -- Executing [s at macro-outbound-callerid:16] ExecIf("IAX2/0117211900-1067", "0?Set(CALLERID(all)=)") in new stack
    -- Executing [s at macro-outbound-callerid:17] ExecIf("IAX2/0117211900-1067", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
    -- Executing [s at macro-outbound-callerid:18] Set("IAX2/0117211900-1067", "CDR(outbound_cnum)=0861179739") in new stack
    -- Executing [s at macro-outbound-callerid:19] Set("IAX2/0117211900-1067", "CDR(outbound_cnam)=Syrex") in new stack
    -- Executing [s at macro-dialout-trunk:12] GosubIf("IAX2/0117211900-1067", "1?sub-flp-3,s,1()") in new stack
    -- Executing [s at sub-flp-3:1] ExecIf("IAX2/0117211900-1067", "0?Return()") in new stack
    -- Executing [s at sub-flp-3:2] ExecIf("IAX2/0117211900-1067", "0?Return()") in new stack
    -- Executing [s at sub-flp-3:3] ExecIf("IAX2/0117211900-1067", "0?Return()") in new stack
    -- Executing [s at sub-flp-3:4] ExecIf("IAX2/0117211900-1067", "1?Set(TARGET_FLP_3=27110509058)") in new stack
    -- Executing [s at sub-flp-3:5] GotoIf("IAX2/0117211900-1067", "1?match") in new stack
    -- Goto (sub-flp-3,s,13)
    -- Executing [s at sub-flp-3:13] Set("IAX2/0117211900-1067", "DIAL_NUMBER=27110509058") in new stack
    -- Executing [s at sub-flp-3:14] Return("IAX2/0117211900-1067", "") in new stack
    -- Executing [s at macro-dialout-trunk:13] Set("IAX2/0117211900-1067", "OUTNUM=27110509058") in new stack
    -- Executing [s at macro-dialout-trunk:14] Set("IAX2/0117211900-1067", "custom=AMP") in new stack
    -- Executing [s at macro-dialout-trunk:15] ExecIf("IAX2/0117211900-1067", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)tL(10800000:300000))") in new stack
    -- Executing [s at macro-dialout-trunk:16] ExecIf("IAX2/0117211900-1067", "0?Set(DIAL_TRUNK_OPTIONS=tL(10800000:300000)M(confirm))") in new stack
    -- Executing [s at macro-dialout-trunk:17] Macro("IAX2/0117211900-1067", "dialout-trunk-predial-hook,") in new stack
    -- Executing [s at macro-dialout-trunk-predial-hook:1] NoOp("IAX2/0117211900-1067", "Evaluating Channel for possible accountcode override: IAX2/0117211900-1067") in new stack
    -- Executing [s at macro-dialout-trunk-predial-hook:2] Set("IAX2/0117211900-1067", "CDR(accountcode)=5886269211") in new stack
    -- Executing [s at 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 at macro-dialout-trunk-predial-hook:4] Set("IAX2/0117211900-1067", "CALLERID(all)='"Syrex" <0861179739>'") in new stack
    -- Executing [s at macro-dialout-trunk-predial-hook:5] Set("IAX2/0117211900-1067", "CALLERID(all)='Syrex <0861179739>'") in new stack
    -- Executing [s at 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 at 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 at 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 at 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 at syrex.co.za>;tag=as4dd7c524
To: <sip:0110509058 at 14.122.0.33>
Contact: <sip:0861179739 at 192.25.69.236:5060>
Call-ID: 7249afdb7a50a6d722d5ab386236fd0c at 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 at 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 at syrex.co.za>;tag=as4dd7c524
To: <sip:0110509058 at 14.122.0.33>;tag=c97b4d1cb1f3d0da549e06a8d482ef63.30f4
Call-ID: 7249afdb7a50a6d722d5ab386236fd0c at 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 at 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 at syrex.co.za>;tag=as4dd7c524
To: <sip:0110509058 at 14.122.0.33>;tag=c97b4d1cb1f3d0da549e06a8d482ef63.30f4
Contact: <sip:0861179739 at 192.25.69.236:5060>
Call-ID: 7249afdb7a50a6d722d5ab386236fd0c at 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 at 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 at syrex.co.za>;tag=as4dd7c524
To: <sip:0110509058 at 14.122.0.33>
Contact: <sip:0861179739 at 192.25.69.236:5060>
Call-ID: 7249afdb7a50a6d722d5ab386236fd0c at 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 at 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 at 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 at syrex.co.za>;tag=as4dd7c524
To: <sip:0110509058 at 14.122.0.33>
Call-ID: 7249afdb7a50a6d722d5ab386236fd0c at 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 at syrex.co.za>;tag=as4dd7c524
To: <sip:0110509058 at 14.122.0.33>;tag=as70559c2a
Call-ID: 7249afdb7a50a6d722d5ab386236fd0c at syrex.co.za
CSeq: 103 INVITE
User-Agent: ECN Megaswitch
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
X-StartID: 7249afdb7a50a6d722d5ab386236fd0c at 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 at 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 at syrex.co.za>;tag=as4dd7c524
To: <sip:0110509058 at 14.122.0.33>;tag=as70559c2a
Contact: <sip:0861179739 at 192.25.69.236:5060>
Call-ID: 7249afdb7a50a6d722d5ab386236fd0c at 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 at custom-freepbx-a2billing:1] NoOp("IAX2/0117211900-1067", "h: Dial status: BUSY Hangup cause: 17") in new stack
    -- Executing [h at custom-freepbx-a2billing:2] Set("IAX2/0117211900-1067", "RC=17") in new stack
    -- Executing [h at custom-freepbx-a2billing:3] ExecIf("IAX2/0117211900-1067", "1?Playtones(busy)") in new stack
    -- Executing [h at 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 at 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 at 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 at 192.168.10.53:46522>
To: "0110509058"<sip:0110509058 at lair.co.za>
From: "David Herselman"<sip:1904 at 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 at lair.co.za>;tag=7e5f7034
To: "0110509058"<sip:0110509058 at 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 at 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 at lair.co.za>;tag=as6b328efb
From: "David Herselman"<sip:1904 at 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 at 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 at 192.168.10.53:46522>
To: "0110509058"<sip:0110509058 at lair.co.za>
From: "David Herselman"<sip:1904 at 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 at 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 at 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 at lair.co.za>;tag=7e5f7034
To: "0110509058"<sip:0110509058 at 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 at 192.168.1.11:5060>
Content-Length: 0


<------------>
  == Extension Changed 1904[ext-local] new state InUse for Notify User 1900
    -- Executing [0110509058 at from-internal:1] Macro("SIP/1904-0000a921", "user-callerid,LIMIT,EXTERNAL,") in new stack
    -- Executing [s at macro-user-callerid:1] Set("SIP/1904-0000a921", "TOUCH_MONITOR=1404332606.93170") in new stack
    -- Executing [s at macro-user-callerid:2] Set("SIP/1904-0000a921", "AMPUSER=1904") in new stack
    -- Executing [s at macro-user-callerid:3] GotoIf("SIP/1904-0000a921", "0?report") in new stack
    -- Executing [s at macro-user-callerid:4] ExecIf("SIP/1904-0000a921", "1?Set(REALCALLERIDNUM=1904)") in new stack
    -- Executing [s at macro-user-callerid:5] Set("SIP/1904-0000a921", "AMPUSER=1904") in new stack
    -- Executing [s at macro-user-callerid:6] GotoIf("SIP/1904-0000a921", "0?limit") in new stack
    -- Executing [s at macro-user-callerid:7] Set("SIP/1904-0000a921", "AMPUSERCIDNAME=David Herselman") in new stack
    -- Executing [s at macro-user-callerid:8] GotoIf("SIP/1904-0000a921", "0?report") in new stack
    -- Executing [s at macro-user-callerid:9] Set("SIP/1904-0000a921", "AMPUSERCID=1904") in new stack
    -- Executing [s at macro-user-callerid:10] Set("SIP/1904-0000a921", "__DIAL_OPTIONS=trL(10800000:300000)") in new stack
    -- Executing [s at macro-user-callerid:11] Set("SIP/1904-0000a921", "CALLERID(all)="David Herselman" <1904>") in new stack
    -- Executing [s at macro-user-callerid:12] GotoIf("SIP/1904-0000a921", "0?limit") in new stack
    -- Executing [s at macro-user-callerid:13] ExecIf("SIP/1904-0000a921", "1?Set(GROUP(concurrency_limit)=1904)") in new stack
    -- Executing [s at macro-user-callerid:14] GosubIf("SIP/1904-0000a921", "7?sub-ccss,s,1(from-internal,0110509058)") in new stack
    -- Executing [s at sub-ccss:1] ExecIf("SIP/1904-0000a921", "0?Return()") in new stack
    -- Executing [s at sub-ccss:2] Set("SIP/1904-0000a921", "CCSS_SETUP=TRUE") in new stack
    -- Executing [s at 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 at sub-ccss:1] GotoIf("SIP/1904-0000a921", "0?is_exten") in new stack
    -- Executing [monitor_default at sub-ccss:2] StackPop("SIP/1904-0000a921", "") in new stack
    -- Executing [monitor_default at sub-ccss:3] Return("SIP/1904-0000a921", "FALSE") in new stack
    -- Executing [s at macro-user-callerid:15] ExecIf("SIP/1904-0000a921", "0?Set(CHANNEL(language)=)") in new stack
    -- Executing [s at macro-user-callerid:16] GotoIf("SIP/1904-0000a921", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,30)
    -- Executing [s at macro-user-callerid:30] Set("SIP/1904-0000a921", "CALLERID(number)=1904") in new stack
    -- Executing [s at macro-user-callerid:31] Set("SIP/1904-0000a921", "CALLERID(name)=David Herselman") in new stack
    -- Executing [s at macro-user-callerid:32] Set("SIP/1904-0000a921", "CDR(cnum)=1904") in new stack
    -- Executing [s at macro-user-callerid:33] Set("SIP/1904-0000a921", "CDR(cnam)=David Herselman") in new stack
    -- Executing [s at macro-user-callerid:34] Set("SIP/1904-0000a921", "CHANNEL(language)=en") in new stack
    -- Executing [0110509058 at from-internal:2] ExecIf("SIP/1904-0000a921", "0 ?Set(CDR(accountcode)=)") in new stack
    -- Executing [0110509058 at from-internal:3] Set("SIP/1904-0000a921", "MOHCLASS=default") in new stack
    -- Executing [0110509058 at from-internal:4] Set("SIP/1904-0000a921", "_NODEST=") in new stack
    -- Executing [0110509058 at from-internal:5] Gosub("SIP/1904-0000a921", "sub-record-check,s,1(out,0110509058,)") in new stack
    -- Executing [s at sub-record-check:1] Set("SIP/1904-0000a921", "REC_POLICY_MODE_SAVE=") in new stack
    -- Executing [s at sub-record-check:2] GotoIf("SIP/1904-0000a921", "1?check") in new stack
    -- Goto (sub-record-check,s,7)
    -- Executing [s at sub-record-check:7] Set("SIP/1904-0000a921", "__MON_FMT=wav") in new stack
    -- Executing [s at sub-record-check:8] GotoIf("SIP/1904-0000a921", "1?next") in new stack
    -- Goto (sub-record-check,s,11)
    -- Executing [s at sub-record-check:11] ExecIf("SIP/1904-0000a921", "0?Return()") in new stack
    -- Executing [s at sub-record-check:12] ExecIf("SIP/1904-0000a921", "0?Set(__REC_POLICY_MODE=)") in new stack
    -- Executing [s at sub-record-check:13] GotoIf("SIP/1904-0000a921", "0?out,1") in new stack
    -- Executing [s at sub-record-check:14] Set("SIP/1904-0000a921", "__REC_STATUS=INITIALIZED") in new stack
    -- Executing [s at sub-record-check:15] Set("SIP/1904-0000a921", "NOW=1404332606") in new stack
    -- Executing [s at sub-record-check:16] Set("SIP/1904-0000a921", "__DAY=02") in new stack
    -- Executing [s at sub-record-check:17] Set("SIP/1904-0000a921", "__MONTH=07") in new stack
    -- Executing [s at sub-record-check:18] Set("SIP/1904-0000a921", "__YEAR=2014") in new stack
    -- Executing [s at sub-record-check:19] Set("SIP/1904-0000a921", "__TIMESTR=20140702-222326") in new stack
    -- Executing [s at sub-record-check:20] Set("SIP/1904-0000a921", "__FROMEXTEN=1904") in new stack
    -- Executing [s at sub-record-check:21] Set("SIP/1904-0000a921", "__CALLFILENAME=out-0110509058-1904-20140702-222326-1404332606.93170") in new stack
    -- Executing [s at sub-record-check:22] Goto("SIP/1904-0000a921", "out,1") in new stack
    -- Goto (sub-record-check,out,1)
    -- Executing [out at sub-record-check:1] ExecIf("SIP/1904-0000a921", "1?Set(__REC_POLICY_MODE=always)") in new stack
    -- Executing [out at sub-record-check:2] GosubIf("SIP/1904-0000a921", "1?record,1(exten,0110509058,1904)") in new stack
    -- Executing [record at sub-record-check:1] Set("SIP/1904-0000a921", "AUDIOHOOK_INHERIT(MixMonitor)=yes") in new stack
    -- Executing [record at sub-record-check:2] MixMonitor("SIP/1904-0000a921", "2014/07/02/out-0110509058-1904-20140702-222326-1404332606.93170.wav,,") in new stack
    -- Executing [record at sub-record-check:3] Set("SIP/1904-0000a921", "__REC_STATUS=RECORDING") in new stack
    -- Executing [record at sub-record-check:4] Set("SIP/1904-0000a921", "CDR(recordingfile)=out-0110509058-1904-20140702-222326-1404332606.93170.wav") in new stack
    -- Executing [record at sub-record-check:5] Return("SIP/1904-0000a921", "") in new stack
    -- Executing [out at sub-record-check:3] Return("SIP/1904-0000a921", "") in new stack
  == Begin MixMonitor Recording SIP/1904-0000a921
    -- Executing [0110509058 at from-internal:6] Macro("SIP/1904-0000a921", "dialout-trunk,7,110509058,,off") in new stack
    -- Executing [s at macro-dialout-trunk:1] Set("SIP/1904-0000a921", "DIAL_TRUNK=7") in new stack
    -- Executing [s at macro-dialout-trunk:2] GosubIf("SIP/1904-0000a921", "0?sub-pincheck,s,1()") in new stack
    -- Executing [s at macro-dialout-trunk:3] GotoIf("SIP/1904-0000a921", "0?disabletrunk,1") in new stack
    -- Executing [s at macro-dialout-trunk:4] Set("SIP/1904-0000a921", "DIAL_NUMBER=110509058") in new stack
    -- Executing [s at macro-dialout-trunk:5] Set("SIP/1904-0000a921", "DIAL_TRUNK_OPTIONS=trL(10800000:300000)") in new stack
    -- Executing [s at macro-dialout-trunk:6] Set("SIP/1904-0000a921", "OUTBOUND_GROUP=OUT_7") in new stack
    -- Executing [s at macro-dialout-trunk:7] GotoIf("SIP/1904-0000a921", "1?nomax") in new stack
    -- Goto (macro-dialout-trunk,s,9)
    -- Executing [s at macro-dialout-trunk:9] GotoIf("SIP/1904-0000a921", "0?skipoutcid") in new stack
    -- Executing [s at macro-dialout-trunk:10] Set("SIP/1904-0000a921", "DIAL_TRUNK_OPTIONS=tL(10800000:300000)") in new stack
    -- Executing [s at macro-dialout-trunk:11] Macro("SIP/1904-0000a921", "outbound-callerid,7") in new stack
    -- Executing [s at macro-outbound-callerid:1] ExecIf("SIP/1904-0000a921", "0?Set(CALLERPRES()=)") in new stack
    -- Executing [s at macro-outbound-callerid:2] ExecIf("SIP/1904-0000a921", "0?Set(REALCALLERIDNUM=1904)") in new stack
    -- Executing [s at macro-outbound-callerid:3] GotoIf("SIP/1904-0000a921", "1?normcid") in new stack
    -- Goto (macro-outbound-callerid,s,6)
    -- Executing [s at macro-outbound-callerid:6] Set("SIP/1904-0000a921", "USEROUTCID=") in new stack
    -- Executing [s at macro-outbound-callerid:7] Set("SIP/1904-0000a921", "EMERGENCYCID=") in new stack
    -- Executing [s at macro-outbound-callerid:8] Set("SIP/1904-0000a921", "TRUNKOUTCID="Syrex" <0861179739>") in new stack
    -- Executing [s at macro-outbound-callerid:9] GotoIf("SIP/1904-0000a921", "1?trunkcid") in new stack
    -- Goto (macro-outbound-callerid,s,14)
    -- Executing [s at macro-outbound-callerid:14] ExecIf("SIP/1904-0000a921", "1?Set(CALLERID(all)="Syrex" <0861179739>)") in new stack
    -- Executing [s at macro-outbound-callerid:15] ExecIf("SIP/1904-0000a921", "0?Set(CALLERID(all)=)") in new stack
    -- Executing [s at macro-outbound-callerid:16] ExecIf("SIP/1904-0000a921", "0?Set(CALLERID(all)=)") in new stack
    -- Executing [s at macro-outbound-callerid:17] ExecIf("SIP/1904-0000a921", "0?Set(CALLERPRES()=prohib_passed_screen)") in new stack
    -- Executing [s at macro-outbound-callerid:18] Set("SIP/1904-0000a921", "CDR(outbound_cnum)=0861179739") in new stack
    -- Executing [s at macro-outbound-callerid:19] Set("SIP/1904-0000a921", "CDR(outbound_cnam)=Syrex") in new stack
    -- Executing [s at macro-dialout-trunk:12] GosubIf("SIP/1904-0000a921", "1?sub-flp-7,s,1()") in new stack
    -- Executing [s at sub-flp-7:1] ExecIf("SIP/1904-0000a921", "0?Return()") in new stack
    -- Executing [s at sub-flp-7:2] ExecIf("SIP/1904-0000a921", "0?Return()") in new stack
    -- Executing [s at sub-flp-7:3] ExecIf("SIP/1904-0000a921", "0?Return()") in new stack
    -- Executing [s at sub-flp-7:4] ExecIf("SIP/1904-0000a921", "1?Set(TARGET_FLP_7=0110509058)") in new stack
    -- Executing [s at sub-flp-7:5] GotoIf("SIP/1904-0000a921", "1?match") in new stack
    -- Goto (sub-flp-7,s,15)
    -- Executing [s at sub-flp-7:15] Set("SIP/1904-0000a921", "DIAL_NUMBER=0110509058") in new stack
    -- Executing [s at sub-flp-7:16] Return("SIP/1904-0000a921", "") in new stack
    -- Executing [s at macro-dialout-trunk:13] Set("SIP/1904-0000a921", "OUTNUM=0110509058") in new stack
    -- Executing [s at macro-dialout-trunk:14] Set("SIP/1904-0000a921", "custom=IAX2/Syrex") in new stack
    -- Executing [s at macro-dialout-trunk:15] ExecIf("SIP/1904-0000a921", "0?Set(DIAL_TRUNK_OPTIONS=M(setmusic^default)tL(10800000:300000))") in new stack
    -- Executing [s at macro-dialout-trunk:16] ExecIf("SIP/1904-0000a921", "0?Set(DIAL_TRUNK_OPTIONS=tL(10800000:300000)M(confirm))") in new stack
    -- Executing [s at macro-dialout-trunk:17] Macro("SIP/1904-0000a921", "dialout-trunk-predial-hook,") in new stack
    -- Executing [s at macro-dialout-trunk-predial-hook:1] Set("SIP/1904-0000a921", "CALLERID(num)=0861179739") in new stack
    -- Executing [s at macro-dialout-trunk-predial-hook:2] SIPAddHeader("SIP/1904-0000a921", "X-CallerID:"Syrex" <0861179739>") in new stack
    -- Executing [s at macro-dialout-trunk-predial-hook:3] Set("SIP/1904-0000a921", "IAXVAR(X-CallerID)="Syrex" <0861179739>") in new stack
    -- Executing [s at macro-dialout-trunk:18] GotoIf("SIP/1904-0000a921", "0?bypass,1") in new stack
    -- Executing [s at macro-dialout-trunk:19] ExecIf("SIP/1904-0000a921", "1?Set(CONNECTEDLINE(num,i)=0110509058)") in new stack
    -- Executing [s at macro-dialout-trunk:20] ExecIf("SIP/1904-0000a921", "1?Set(CONNECTEDLINE(name,i)=CID:0861179739)") in new stack
    -- Executing [s at macro-dialout-trunk:21] GotoIf("SIP/1904-0000a921", "0?customtrunk") in new stack
    -- Executing [s at 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 at lair.co.za>;tag=7e5f7034
To: "0110509058"<sip:0110509058 at 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 at 192.168.1.11:5060>
P-Asserted-Identity: "CID:0861179739" <sip:0110509058 at 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 at lair.co.za>;tag=7e5f7034
To: "0110509058"<sip:0110509058 at 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 at 192.168.1.11:5060>
P-Asserted-Identity: "CID:0861179739" <sip:0110509058 at 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 at 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 at 192.168.10.53:46522>
To: "0110509058"<sip:0110509058 at lair.co.za>;tag=as33aa39e7
From: "David Herselman"<sip:1904 at 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 at 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 at 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 at 192.168.10.53:46522>
To: "0110509058"<sip:0110509058 at lair.co.za>;tag=as33aa39e7
From: "David Herselman"<sip:1904 at 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 at 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 at macro-dialout-trunk:1] Macro("SIP/1904-0000a921", "hangupcall,") in new stack
    -- Executing [s at macro-hangupcall:1] GotoIf("SIP/1904-0000a921", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s at macro-hangupcall:3] ExecIf("SIP/1904-0000a921", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s at 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 at 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 at 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 at lair.co.za>;tag=as33aa39e7
To: "David Herselman"<sip:1904 at 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 at 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 at lair.co.za>;tag=as33aa39e7
To: "David Herselman"<sip:1904 at 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 at 192.168.10.53:46522>
To: "David Herselman"<sip:1904 at lair.co.za>;tag=7e5f7034
From: "0110509058"<sip:0110509058 at 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 at 192.168.10.53:46522>
To: "David Herselman"<sip:1904 at lair.co.za>;tag=7e5f7034
From: "0110509058"<sip:0110509058 at 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}


> IAX2 trunk dial status and hangup cause not sent to SIP endpoint
> ----------------------------------------------------------------
>
>                 Key: ASTERISK-23979
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-23979
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Channels/chan_sip/General
>    Affects Versions: 11.9.0
>         Environment: IAX2 trunk with SIP end points
>            Reporter: David Herselman
>            Assignee: David Herselman
>            Severity: Critical
>
> 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 at 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 at custom-freepbx-a2billing:1] NoOp("IAX2/0117211900-2043", "h: Dial status: BUSY Hangup cause: 17") in new stack
>     -- Executing [h at custom-freepbx-a2billing:2] Set("IAX2/0117211900-2043", "RC=17") in new stack
>     -- Executing [h at custom-freepbx-a2billing:3] ExecIf("IAX2/0117211900-2043", "1?Playtones(busy)") in new stack
>     -- Executing [h at 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 at 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 at 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 at lair.co.za>;tag=455f2257
> To: "0110509058"<sip:0110509058 at 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 at 192.168.1.11:5060>
> P-Asserted-Identity: "CID:0861179739" <sip:0110509058 at 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 at lair.co.za>;tag=455f2257
> To: "0110509058"<sip:0110509058 at 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 at 192.168.1.11:5060>
> P-Asserted-Identity: "CID:0861179739" <sip:0110509058 at 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 at 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 at 192.168.10.53:11468>
> To: "0110509058"<sip:0110509058 at lair.co.za>;tag=as3b114d0c
> From: "David Herselman"<sip:1904 at 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 at 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 at 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 at 192.168.10.53:11468>
> To: "0110509058"<sip:0110509058 at lair.co.za>;tag=as3b114d0c
> From: "David Herselman"<sip:1904 at 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 at 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 at macro-dialout-trunk:1] NoOp("SIP/1904-00009c84", "h: Dial status: ANSWER Hangup cause: 16") in new stack
>     -- Executing [h at macro-dialout-trunk:2] ExecIf("SIP/1904-00009c84", "0?Goto(macro-dialout-trunk,s-BUSY,1)") in new stack
>     -- Executing [h at macro-dialout-trunk:3] Macro("SIP/1904-00009c84", "hangupcall,") in new stack
>     -- Executing [s at macro-hangupcall:1] GotoIf("SIP/1904-00009c84", "1?theend") in new stack
>     -- Goto (macro-hangupcall,s,3)
>     -- Executing [s at macro-hangupcall:3] ExecIf("SIP/1904-00009c84", "0?Set(CDR(recordingfile)=)") in new stack
>     -- Executing [s at 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 at 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 at 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 at lair.co.za>;tag=as3b114d0c
> To: "David Herselman"<sip:1904 at 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 at 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 at lair.co.za>;tag=as3b114d0c
> To: "David Herselman"<sip:1904 at 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 at 192.168.10.53:11468>
> To: "David Herselman"<sip:1904 at lair.co.za>;tag=455f2257
> From: "0110509058"<sip:0110509058 at 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 at 192.168.10.53:11468>
> To: "David Herselman"<sip:1904 at lair.co.za>;tag=455f2257
> From: "0110509058"<sip:0110509058 at lair.co.za>;tag=as3b114d0c
> Call-ID: NTBkYjFmYTYwNmNiMDZmN2E5ZWU1ZDkwM2JiNWExMGU.
> CSeq: 102 BYE
> User-Agent: eyeBeam release 1102u stamp 52344
> Content-Length: 0
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.2#6252)



More information about the asterisk-bugs mailing list