[Oct 19 14:23:03] VERBOSE[21480] manager.c:   == Manager 'admin' logged on from 127.0.0.1
[Oct 19 14:23:03] VERBOSE[21480] manager.c:   == Manager 'admin' logged off from 127.0.0.1
[Oct 19 16:32:23] VERBOSE[21480] app_mixmonitor.c:   == Begin MixMonitor Recording SIP/voipms-00005eb1
[Oct 19 16:32:30] VERBOSE[21480] app_mixmonitor.c:   == MixMonitor close filestream
[Oct 19 16:32:30] VERBOSE[21480] app_mixmonitor.c:   == End MixMonitor Recording SIP/voipms-00005eb1
[Oct 19 17:40:52] DEBUG[21480] pbx.c: Launching 'Log'
[Oct 19 17:40:52] VERBOSE[21480] pbx.c:     -- Executing [DIALCUSTOMER@DIALPLAN-1:1] Log("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "NOTICE,NEXTCALL") in new stack
[Oct 19 17:40:52] NOTICE[21480] Ext. DIALCUSTOMER: NEXTCALL
[Oct 19 17:40:52] DEBUG[21480] pbx.c: Result of 'CALL_ID' is '1909303'
[Oct 19 17:40:52] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:52] VERBOSE[21480] pbx.c:     -- Executing [DIALCUSTOMER@DIALPLAN-1:2] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CDR(userfield)=1909303") in new stack
[Oct 19 17:40:52] DEBUG[21480] pbx.c: Result of 'CALL_ID' is '1909303'
[Oct 19 17:40:52] DEBUG[21480] pbx.c: Launching 'AGI'
[Oct 19 17:40:52] VERBOSE[21480] pbx.c:     -- Executing [DIALCUSTOMER@DIALPLAN-1:3] AGI("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "set_disposition.php,1909303,DIALING,1") in new stack
[Oct 19 17:40:52] VERBOSE[21480] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/set_disposition.php
[Oct 19 17:40:53] VERBOSE[21480] res_agi.c:     -- <Local/DIALCUSTOMER@DIALPLAN-1-1bad;2>AGI Script set_disposition.php completed, returning 0
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Result of 'NUMBER' is '19517855687'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Launching 'AGI'
[Oct 19 17:40:53] VERBOSE[21480] pbx.c:     -- Executing [DIALCUSTOMER@DIALPLAN-1:4] AGI("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "get_ani.php,19517855687") in new stack
[Oct 19 17:40:53] VERBOSE[21480] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/get_ani.php
[Oct 19 17:40:53] VERBOSE[21480] res_agi.c:     -- <Local/DIALCUSTOMER@DIALPLAN-1-1bad;2>AGI Script get_ani.php completed, returning 0
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Result of 'CALL_ID' is '1909303'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Result of 'NUMBER' is '19517855687'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Result of 'RING_TIME' is '60'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Launching 'Macro'
[Oct 19 17:40:53] VERBOSE[21480] pbx.c:     -- Executing [DIALCUSTOMER@DIALPLAN-1:5] Macro("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "direct-dial,1,1909303,19517855687,60") in new stack
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Result of 'ARG1' is '1'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:53] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:1] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_ATTEMPT=1") in new stack
[Oct 19 17:40:53] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '1'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Result of 'CARRIER1' is 'SIP/checkbox'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Function result is 'SIP/checkbox'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:53] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:2] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CARRIER=SIP/checkbox") in new stack
[Oct 19 17:40:53] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Result of 'ARG2' is '1909303'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/checkbox'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Launching 'AGI'
[Oct 19 17:40:53] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:3] AGI("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "call_queue_log.php,1909303,SIP/checkbox,DIALING") in new stack
[Oct 19 17:40:53] VERBOSE[21480] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/call_queue_log.php
[Oct 19 17:40:53] VERBOSE[21480] res_agi.c:     -- <Local/DIALCUSTOMER@DIALPLAN-1-1bad;2>AGI Script call_queue_log.php completed, returning 0
[Oct 19 17:40:53] DEBUG[21480] app_macro.c: Executed application: AGI
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:53] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:4] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_CONNECTED=0") in new stack
[Oct 19 17:40:53] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/checkbox'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Result of 'ARG3' is '19517855687'
[Oct 19 17:40:53] DEBUG[21480] pbx.c: Launching 'Dial'
[Oct 19 17:40:53] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:5] Dial("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "SIP/checkbox/19517855687,60") in new stack
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: Asked to create a SIP channel with formats: 0x40 (slin)
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: Allocating new SIP dialog for 2d5656e0024b4f7e10d0233f7ec7812d@192.168.100.104:0 - INVITE (No RTP)
[Oct 19 17:40:53] DEBUG[21480] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2aaaf002f0d8'
[Oct 19 17:40:53] DEBUG[21480] res_rtp_asterisk.c: Allocated port 17280 for RTP instance '0x2aaaf002f0d8'
[Oct 19 17:40:53] DEBUG[21480] rtp_engine.c: RTP instance '0x2aaaf002f0d8' is setup and ready to go
[Oct 19 17:40:53] DEBUG[21480] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2aaaf002f0d8'
[Oct 19 17:40:53] VERBOSE[21480] netsock2.c:   == Using SIP RTP CoS mark 5
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: Setting NAT on RTP to On
[Oct 19 17:40:53] DEBUG[21480] acl.c: For destination '74.55.161.234', our source address is '192.168.100.104'.
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.100.104:5060
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: *** Our native formats are 0x100 (g729) 
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: *** Joint capabilities are 0x0 (nothing) 
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: *** Our capabilities are 0x100 (g729) 
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729) 
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: *** Our preferred formats from the incoming channel are 0x40 (slin) 
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: This channel will not be able to handle video.
[Oct 19 17:40:53] DEBUG[21480] rtp_engine.c: Can't find native functions for channel 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:40:53] DEBUG[21480] rtp_engine.c: Seeded SDP of 'SIP/checkbox-00006e24' with that of 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable DIALEDTIME.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable ANSWEREDTIME.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable DIALEDPEERNAME.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable DIALEDPEERNUMBER.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable DIALSTATUS.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable MACRO_DEPTH.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable CALL_CONNECTED.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable AGISTATUS.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable CARRIER.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable CALL_ATTEMPT.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable ARG4.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable ARG3.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable ARG2.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable ARG1.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable MACRO_PRIORITY.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable MACRO_CONTEXT.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable MACRO_EXTEN.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable ANI.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable DISPO_RESULT.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable RING_TIME.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable CALL_ID.
[Oct 19 17:40:53] DEBUG[21480] channel.c: Not copying variable NUMBER.
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: Outgoing Call for 19517855687
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: Updating call counter for outgoing call
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: ** Our capability: 0x100 (g729) Video flag: False Text flag: False
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: ** Our prefcodec: 0x40 (slin) 
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: -- Done with adding codecs to SDP
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: Done building SDP. Settling with this capability: 0x100 (g729)
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: Initializing initreq for method INVITE - callid 77bc2f9f4c5dabd266a7960d5057f41d@74.55.161.234
[Oct 19 17:40:53] DEBUG[21480] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 74.55.161.234:5060
[Oct 19 17:40:53] VERBOSE[21480] app_dial.c:     -- Called SIP/checkbox/19517855687
[Oct 19 17:40:53] DEBUG[21480] channel.c: Set channel SIP/checkbox-00006e24 to read format slin
[Oct 19 17:40:53] DEBUG[21480] channel.c: Set channel SIP/checkbox-00006e24 to write format slin
[Oct 19 17:40:56] DEBUG[21480] channel.c: Hanging up channel 'SIP/checkbox-00006e24'
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Hangup call SIP/checkbox-00006e24, SIP callid 77bc2f9f4c5dabd266a7960d5057f41d@74.55.161.234
[Oct 19 17:40:56] DEBUG[21480] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2aaaf002f0d8'
[Oct 19 17:40:56] VERBOSE[21480] app_dial.c:   == Everyone is busy/congested at this time (1:0/0/1)
[Oct 19 17:40:56] DEBUG[21480] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL.
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Dial
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:6] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_CONNECTED=1") in new stack
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'ARG2' is '1909303'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/checkbox'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'AGI'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:7] AGI("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "call_queue_log.php,1909303,SIP/checkbox,CHANUNAVAIL") in new stack
[Oct 19 17:40:56] VERBOSE[21480] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/call_queue_log.php
[Oct 19 17:40:56] VERBOSE[21480] res_agi.c:     -- <Local/DIALCUSTOMER@DIALPLAN-1-1bad;2>AGI Script call_queue_log.php completed, returning 0
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: AGI
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '1'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'MAX_PROVIDERS' is '4'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Expression result is '0'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'GotoIf'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:8] GotoIf("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "0?s-FAILED,1") in new stack
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Not taking any branch
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: GotoIf
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '1'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Expression result is '2'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:9] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_ATTEMPT=2") in new stack
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'DIALSTATUS' is 'CHANUNAVAIL'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Goto'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:10] Goto("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "s-CHANUNAVAIL,1") in new stack
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Goto (macro-direct-dial,s-CHANUNAVAIL,1)
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Goto
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Goto'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s-CHANUNAVAIL@macro-direct-dial:1] Goto("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "s,2") in new stack
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Goto (macro-direct-dial,s,2)
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Goto
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '2'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CARRIER2' is 'SIP/altavox'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Function result is 'SIP/altavox'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:2] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CARRIER=SIP/altavox") in new stack
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'ARG2' is '1909303'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/altavox'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'AGI'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:3] AGI("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "call_queue_log.php,1909303,SIP/altavox,DIALING") in new stack
[Oct 19 17:40:56] VERBOSE[21480] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/call_queue_log.php
[Oct 19 17:40:56] VERBOSE[21480] res_agi.c:     -- <Local/DIALCUSTOMER@DIALPLAN-1-1bad;2>AGI Script call_queue_log.php completed, returning 0
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: AGI
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:4] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_CONNECTED=0") in new stack
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/altavox'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'ARG3' is '19517855687'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Dial'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:5] Dial("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "SIP/altavox/19517855687,60") in new stack
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Asked to create a SIP channel with formats: 0x40 (slin)
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Allocating new SIP dialog for 6b89432011ee689a4e0d9dc827f9df2d@192.168.100.104:0 - INVITE (No RTP)
[Oct 19 17:40:56] DEBUG[21480] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2aaaf8170b38'
[Oct 19 17:40:56] DEBUG[21480] res_rtp_asterisk.c: Allocated port 16442 for RTP instance '0x2aaaf8170b38'
[Oct 19 17:40:56] DEBUG[21480] rtp_engine.c: RTP instance '0x2aaaf8170b38' is setup and ready to go
[Oct 19 17:40:56] DEBUG[21480] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2aaaf8170b38'
[Oct 19 17:40:56] VERBOSE[21480] netsock2.c:   == Using SIP RTP CoS mark 5
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Setting NAT on RTP to On
[Oct 19 17:40:56] DEBUG[21480] acl.c: For destination '173.226.228.101', our source address is '192.168.100.104'.
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.100.104:5060
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: *** Our native formats are 0x100 (g729) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: *** Joint capabilities are 0x0 (nothing) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: *** Our capabilities are 0x100 (g729) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: *** Our preferred formats from the incoming channel are 0x40 (slin) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: This channel will not be able to handle video.
[Oct 19 17:40:56] DEBUG[21480] rtp_engine.c: Can't find native functions for channel 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:40:56] DEBUG[21480] rtp_engine.c: Seeded SDP of 'SIP/altavox-00006e28' with that of 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable DIALEDTIME.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ANSWEREDTIME.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable DIALEDPEERNAME.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable DIALEDPEERNUMBER.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable DIALSTATUS.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable MACRO_DEPTH.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable CALL_CONNECTED.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable AGISTATUS.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable CARRIER.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable CALL_ATTEMPT.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ~HASH~SIP_CAUSE~SIP/checkbox-00006e24~.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ARG4.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ARG3.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ARG2.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ARG1.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable MACRO_PRIORITY.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable MACRO_CONTEXT.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable MACRO_EXTEN.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ANI.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable DISPO_RESULT.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable RING_TIME.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable CALL_ID.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable NUMBER.
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Outgoing Call for 19517855687
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Updating call counter for outgoing call
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: ** Our capability: 0x100 (g729) Video flag: False Text flag: False
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: ** Our prefcodec: 0x40 (slin) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: -- Done with adding codecs to SDP
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Done building SDP. Settling with this capability: 0x100 (g729)
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Initializing initreq for method INVITE - callid 46fed6f909ae3fc04c462e5c79b590df@proxy50.altavox.net
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 173.226.228.101:5060
[Oct 19 17:40:56] VERBOSE[21480] app_dial.c:     -- Called SIP/altavox/19517855687
[Oct 19 17:40:56] DEBUG[21480] channel.c: Set channel SIP/altavox-00006e28 to read format slin
[Oct 19 17:40:56] DEBUG[21480] channel.c: Set channel SIP/altavox-00006e28 to write format slin
[Oct 19 17:40:56] VERBOSE[21480] app_dial.c:     -- SIP/altavox-00006e28 is circuit-busy
[Oct 19 17:40:56] DEBUG[21480] channel.c: Hanging up channel 'SIP/altavox-00006e28'
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Hangup call SIP/altavox-00006e28, SIP callid 46fed6f909ae3fc04c462e5c79b590df@proxy50.altavox.net
[Oct 19 17:40:56] DEBUG[21480] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2aaaf8170b38'
[Oct 19 17:40:56] VERBOSE[21480] app_dial.c:   == Everyone is busy/congested at this time (1:0/1/0)
[Oct 19 17:40:56] DEBUG[21480] app_dial.c: Exiting with DIALSTATUS=CONGESTION.
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Dial
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:6] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_CONNECTED=1") in new stack
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'ARG2' is '1909303'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/altavox'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'DIALSTATUS' is 'CONGESTION'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'AGI'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:7] AGI("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "call_queue_log.php,1909303,SIP/altavox,CONGESTION") in new stack
[Oct 19 17:40:56] VERBOSE[21480] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/call_queue_log.php
[Oct 19 17:40:56] VERBOSE[21480] res_agi.c:     -- <Local/DIALCUSTOMER@DIALPLAN-1-1bad;2>AGI Script call_queue_log.php completed, returning 0
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: AGI
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '2'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'MAX_PROVIDERS' is '4'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Expression result is '0'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'GotoIf'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:8] GotoIf("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "0?s-FAILED,1") in new stack
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Not taking any branch
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: GotoIf
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '2'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Expression result is '3'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:9] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_ATTEMPT=3") in new stack
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'DIALSTATUS' is 'CONGESTION'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Goto'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:10] Goto("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "s-CONGESTION,1") in new stack
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Goto (macro-direct-dial,s-CONGESTION,1)
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Goto
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Goto'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s-CONGESTION@macro-direct-dial:1] Goto("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "s,2") in new stack
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Goto (macro-direct-dial,s,2)
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Goto
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '3'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CARRIER3' is 'SIP/vonfone'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Function result is 'SIP/vonfone'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:2] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CARRIER=SIP/vonfone") in new stack
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'ARG2' is '1909303'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/vonfone'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'AGI'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:3] AGI("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "call_queue_log.php,1909303,SIP/vonfone,DIALING") in new stack
[Oct 19 17:40:56] VERBOSE[21480] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/call_queue_log.php
[Oct 19 17:40:56] VERBOSE[21480] res_agi.c:     -- <Local/DIALCUSTOMER@DIALPLAN-1-1bad;2>AGI Script call_queue_log.php completed, returning 0
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: AGI
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:4] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_CONNECTED=0") in new stack
[Oct 19 17:40:56] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/vonfone'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Result of 'ARG3' is '19517855687'
[Oct 19 17:40:56] DEBUG[21480] pbx.c: Launching 'Dial'
[Oct 19 17:40:56] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:5] Dial("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "SIP/vonfone/19517855687,60") in new stack
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Asked to create a SIP channel with formats: 0x40 (slin)
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Allocating new SIP dialog for 1e5a1b6e6f80fc1b20c2a91e7a705a1b@192.168.100.104:0 - INVITE (No RTP)
[Oct 19 17:40:56] DEBUG[21480] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2aaaf40b1098'
[Oct 19 17:40:56] DEBUG[21480] res_rtp_asterisk.c: Allocated port 12078 for RTP instance '0x2aaaf40b1098'
[Oct 19 17:40:56] DEBUG[21480] rtp_engine.c: RTP instance '0x2aaaf40b1098' is setup and ready to go
[Oct 19 17:40:56] DEBUG[21480] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2aaaf40b1098'
[Oct 19 17:40:56] VERBOSE[21480] netsock2.c:   == Using SIP RTP CoS mark 5
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Setting NAT on RTP to On
[Oct 19 17:40:56] DEBUG[21480] acl.c: For destination '174.127.127.219', our source address is '192.168.100.104'.
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.100.104:5060
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: *** Our native formats are 0x100 (g729) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: *** Joint capabilities are 0x0 (nothing) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: *** Our capabilities are 0x100 (g729) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: *** Our preferred formats from the incoming channel are 0x40 (slin) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: This channel will not be able to handle video.
[Oct 19 17:40:56] DEBUG[21480] rtp_engine.c: Can't find native functions for channel 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:40:56] DEBUG[21480] rtp_engine.c: Seeded SDP of 'SIP/vonfone-00006e29' with that of 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable DIALEDTIME.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ANSWEREDTIME.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable DIALEDPEERNAME.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable DIALEDPEERNUMBER.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable DIALSTATUS.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable MACRO_DEPTH.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable CALL_CONNECTED.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable AGISTATUS.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable CARRIER.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable CALL_ATTEMPT.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ~HASH~SIP_CAUSE~SIP/altavox-00006e28~.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ~HASH~SIP_CAUSE~SIP/checkbox-00006e24~.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ARG4.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ARG3.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ARG2.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ARG1.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable MACRO_PRIORITY.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable MACRO_CONTEXT.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable MACRO_EXTEN.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable ANI.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable DISPO_RESULT.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable RING_TIME.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable CALL_ID.
[Oct 19 17:40:56] DEBUG[21480] channel.c: Not copying variable NUMBER.
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Outgoing Call for 19517855687
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Updating call counter for outgoing call
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: ** Our capability: 0x100 (g729) Video flag: False Text flag: False
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: ** Our prefcodec: 0x40 (slin) 
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: -- Done with adding codecs to SDP
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Done building SDP. Settling with this capability: 0x100 (g729)
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Initializing initreq for method INVITE - callid 5794c9d27d4bc4e26301c01c6adddd6d@sbc1.ord.us.vonfone.com
[Oct 19 17:40:56] DEBUG[21480] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 174.127.127.219:5060
[Oct 19 17:40:56] VERBOSE[21480] app_dial.c:     -- Called SIP/vonfone/19517855687
[Oct 19 17:40:56] DEBUG[21480] channel.c: Set channel SIP/vonfone-00006e29 to read format slin
[Oct 19 17:40:56] DEBUG[21480] channel.c: Set channel SIP/vonfone-00006e29 to write format slin
[Oct 19 17:40:57] DEBUG[21480] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2aaaf40b1098'
[Oct 19 17:40:57] DEBUG[21480] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address 4.55.17.198:7564
[Oct 19 17:40:58] DEBUG[21480] res_rtp_asterisk.c: RTCP NAT: Got RTCP from other end. Now sending to address 67.211.162.226:30733
[Oct 19 17:40:58] DEBUG[21480] res_rtp_asterisk.c: Got RTCP report of 58 bytes
[Oct 19 17:40:58] DEBUG[21480] res_rtp_asterisk.c: RTCP Read too short
[Oct 19 17:41:00] DEBUG[21480] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2aaaf40b1098'
[Oct 19 17:41:00] DEBUG[21480] res_rtp_asterisk.c: RTP NAT: Got audio from other end. Now sending to address 67.211.162.226:30732
[Oct 19 17:41:00] DEBUG[21480] app_dial.c: Dunno what to do with control type 26
[Oct 19 17:41:01] VERBOSE[21480] app_dial.c:     -- SIP/vonfone-00006e29 is making progress passing it to Local/DIALCUSTOMER@DIALPLAN-1-1bad;2
[Oct 19 17:41:03] DEBUG[21480] res_rtp_asterisk.c: Got RTCP report of 82 bytes
[Oct 19 17:41:03] VERBOSE[21480] app_dial.c:     -- SIP/vonfone-00006e29 is circuit-busy
[Oct 19 17:41:03] DEBUG[21480] channel.c: Hanging up channel 'SIP/vonfone-00006e29'
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: Hangup call SIP/vonfone-00006e29, SIP callid 5794c9d27d4bc4e26301c01c6adddd6d@sbc1.ord.us.vonfone.com
[Oct 19 17:41:03] DEBUG[21480] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2aaaf40b1098'
[Oct 19 17:41:03] VERBOSE[21480] app_dial.c:   == Everyone is busy/congested at this time (1:0/1/0)
[Oct 19 17:41:03] DEBUG[21480] app_dial.c: Exiting with DIALSTATUS=CONGESTION.
[Oct 19 17:41:03] DEBUG[21480] app_macro.c: Executed application: Dial
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:6] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_CONNECTED=1") in new stack
[Oct 19 17:41:03] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'ARG2' is '1909303'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/vonfone'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'DIALSTATUS' is 'CONGESTION'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Launching 'AGI'
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:7] AGI("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "call_queue_log.php,1909303,SIP/vonfone,CONGESTION") in new stack
[Oct 19 17:41:03] VERBOSE[21480] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/call_queue_log.php
[Oct 19 17:41:03] VERBOSE[21480] res_agi.c:     -- <Local/DIALCUSTOMER@DIALPLAN-1-1bad;2>AGI Script call_queue_log.php completed, returning 0
[Oct 19 17:41:03] DEBUG[21480] app_macro.c: Executed application: AGI
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '3'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'MAX_PROVIDERS' is '4'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Expression result is '0'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Launching 'GotoIf'
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:8] GotoIf("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "0?s-FAILED,1") in new stack
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Not taking any branch
[Oct 19 17:41:03] DEBUG[21480] app_macro.c: Executed application: GotoIf
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '3'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Expression result is '4'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:9] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_ATTEMPT=4") in new stack
[Oct 19 17:41:03] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'DIALSTATUS' is 'CONGESTION'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Launching 'Goto'
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:10] Goto("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "s-CONGESTION,1") in new stack
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Goto (macro-direct-dial,s-CONGESTION,1)
[Oct 19 17:41:03] DEBUG[21480] app_macro.c: Executed application: Goto
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Launching 'Goto'
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Executing [s-CONGESTION@macro-direct-dial:1] Goto("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "s,2") in new stack
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Goto (macro-direct-dial,s,2)
[Oct 19 17:41:03] DEBUG[21480] app_macro.c: Executed application: Goto
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '4'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'CARRIER4' is 'SIP/voipms'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Function result is 'SIP/voipms'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:2] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CARRIER=SIP/voipms") in new stack
[Oct 19 17:41:03] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'ARG2' is '1909303'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/voipms'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Launching 'AGI'
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:3] AGI("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "call_queue_log.php,1909303,SIP/voipms,DIALING") in new stack
[Oct 19 17:41:03] VERBOSE[21480] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/call_queue_log.php
[Oct 19 17:41:03] VERBOSE[21480] res_agi.c:     -- <Local/DIALCUSTOMER@DIALPLAN-1-1bad;2>AGI Script call_queue_log.php completed, returning 0
[Oct 19 17:41:03] DEBUG[21480] app_macro.c: Executed application: AGI
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:4] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_CONNECTED=0") in new stack
[Oct 19 17:41:03] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/voipms'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Result of 'ARG3' is '19517855687'
[Oct 19 17:41:03] DEBUG[21480] pbx.c: Launching 'Dial'
[Oct 19 17:41:03] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:5] Dial("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "SIP/voipms/19517855687,60") in new stack
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: Asked to create a SIP channel with formats: 0x40 (slin)
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: Allocating new SIP dialog for 712a91294bac0aff4318c33a219d9e35@192.168.100.104:0 - INVITE (No RTP)
[Oct 19 17:41:03] DEBUG[21480] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x2aaad8022678'
[Oct 19 17:41:03] DEBUG[21480] res_rtp_asterisk.c: Allocated port 17330 for RTP instance '0x2aaad8022678'
[Oct 19 17:41:03] DEBUG[21480] rtp_engine.c: RTP instance '0x2aaad8022678' is setup and ready to go
[Oct 19 17:41:03] DEBUG[21480] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x2aaad8022678'
[Oct 19 17:41:03] VERBOSE[21480] netsock2.c:   == Using SIP RTP CoS mark 5
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: Setting NAT on RTP to On
[Oct 19 17:41:03] DEBUG[21480] acl.c: For destination '78.129.153.20', our source address is '192.168.100.104'.
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.100.104:5060
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: *** Our native formats are 0x100 (g729) 
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: *** Joint capabilities are 0x0 (nothing) 
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: *** Our capabilities are 0x100 (g729) 
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729) 
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: *** Our preferred formats from the incoming channel are 0x40 (slin) 
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: This channel will not be able to handle video.
[Oct 19 17:41:03] DEBUG[21480] rtp_engine.c: Can't find native functions for channel 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:41:03] DEBUG[21480] rtp_engine.c: Seeded SDP of 'SIP/voipms-00006e34' with that of 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable DIALEDTIME.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable ANSWEREDTIME.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable DIALEDPEERNAME.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable DIALEDPEERNUMBER.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable DIALSTATUS.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable MACRO_DEPTH.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable CALL_CONNECTED.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable AGISTATUS.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable CARRIER.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable CALL_ATTEMPT.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable ~HASH~SIP_CAUSE~SIP/vonfone-00006e29~.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable ~HASH~SIP_CAUSE~SIP/altavox-00006e28~.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable ~HASH~SIP_CAUSE~SIP/checkbox-00006e24~.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable ARG4.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable ARG3.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable ARG2.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable ARG1.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable MACRO_PRIORITY.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable MACRO_CONTEXT.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable MACRO_EXTEN.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable ANI.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable DISPO_RESULT.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable RING_TIME.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable CALL_ID.
[Oct 19 17:41:03] DEBUG[21480] channel.c: Not copying variable NUMBER.
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: Outgoing Call for 19517855687
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: Updating call counter for outgoing call
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: ** Our capability: 0x100 (g729) Video flag: False Text flag: False
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: ** Our prefcodec: 0x40 (slin) 
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: -- Done with adding codecs to SDP
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: Done building SDP. Settling with this capability: 0x100 (g729)
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: Initializing initreq for method INVITE - callid 492efaaf6560c20b771e387d1a8073a3@192.168.100.104:5060
[Oct 19 17:41:03] DEBUG[21480] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 78.129.153.20:5060
[Oct 19 17:41:03] VERBOSE[21480] app_dial.c:     -- Called SIP/voipms/19517855687
[Oct 19 17:41:03] DEBUG[21480] channel.c: Set channel SIP/voipms-00006e34 to read format slin
[Oct 19 17:41:03] DEBUG[21480] channel.c: Set channel SIP/voipms-00006e34 to write format slin
[Oct 19 17:41:11] VERBOSE[21480] app_dial.c:     -- SIP/voipms-00006e34 is busy
[Oct 19 17:41:11] DEBUG[21480] channel.c: Hanging up channel 'SIP/voipms-00006e34'
[Oct 19 17:41:11] DEBUG[21480] chan_sip.c: Hangup call SIP/voipms-00006e34, SIP callid 492efaaf6560c20b771e387d1a8073a3@192.168.100.104:5060
[Oct 19 17:41:11] DEBUG[21480] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x2aaad8022678'
[Oct 19 17:41:11] VERBOSE[21480] app_dial.c:   == Everyone is busy/congested at this time (1:1/0/0)
[Oct 19 17:41:11] DEBUG[21480] app_dial.c: Exiting with DIALSTATUS=BUSY.
[Oct 19 17:41:11] DEBUG[21480] app_macro.c: Executed application: Dial
[Oct 19 17:41:11] DEBUG[21480] pbx.c: Launching 'Set'
[Oct 19 17:41:11] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:6] Set("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "CALL_CONNECTED=1") in new stack
[Oct 19 17:41:11] DEBUG[21480] app_macro.c: Executed application: Set
[Oct 19 17:41:11] DEBUG[21480] pbx.c: Result of 'ARG2' is '1909303'
[Oct 19 17:41:11] DEBUG[21480] pbx.c: Result of 'CARRIER' is 'SIP/voipms'
[Oct 19 17:41:11] DEBUG[21480] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[Oct 19 17:41:11] DEBUG[21480] pbx.c: Launching 'AGI'
[Oct 19 17:41:11] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:7] AGI("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "call_queue_log.php,1909303,SIP/voipms,BUSY") in new stack
[Oct 19 17:41:11] VERBOSE[21480] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/call_queue_log.php
[Oct 19 17:41:11] VERBOSE[21480] res_agi.c:     -- <Local/DIALCUSTOMER@DIALPLAN-1-1bad;2>AGI Script call_queue_log.php completed, returning 0
[Oct 19 17:41:11] DEBUG[21480] app_macro.c: Executed application: AGI
[Oct 19 17:41:11] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '4'
[Oct 19 17:41:11] DEBUG[21480] pbx.c: Result of 'MAX_PROVIDERS' is '4'
[Oct 19 17:41:11] DEBUG[21480] pbx.c: Expression result is '1'
[Oct 19 17:41:11] DEBUG[21480] pbx.c: Launching 'GotoIf'
[Oct 19 17:41:11] VERBOSE[21480] pbx.c:     -- Executing [s@macro-direct-dial:8] GotoIf("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "1?s-FAILED,1") in new stack
[Oct 19 17:41:11] VERBOSE[21480] pbx.c:     -- Goto (macro-direct-dial,s-FAILED,1)
[Oct 19 17:41:11] DEBUG[21480] app_macro.c: Executed application: GotoIf
[Oct 19 17:41:11] DEBUG[21480] pbx.c: Result of 'CALL_ID' is '1909303'
[Oct 19 17:41:11] DEBUG[21480] pbx.c: Launching 'AGI'
[Oct 19 17:41:11] VERBOSE[21480] pbx.c:     -- Executing [s-FAILED@macro-direct-dial:1] AGI("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "set_disposition.php,1909303,FAILED,1") in new stack
[Oct 19 17:41:11] VERBOSE[21480] res_agi.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/set_disposition.php
[Oct 19 17:41:12] VERBOSE[21480] res_agi.c:     -- <Local/DIALCUSTOMER@DIALPLAN-1-1bad;2>AGI Script set_disposition.php completed, returning 0
[Oct 19 17:41:12] DEBUG[21480] app_macro.c: Executed application: AGI
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Launching 'Hangup'
[Oct 19 17:41:12] VERBOSE[21480] pbx.c:     -- Executing [DIALCUSTOMER@DIALPLAN-1:6] Hangup("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "") in new stack
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Spawn extension (DIALPLAN-1,DIALCUSTOMER,6) exited non-zero on 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:41:12] VERBOSE[21480] pbx.c:   == Spawn extension (DIALPLAN-1, DIALCUSTOMER, 6) exited non-zero on 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:41:12] DEBUG[21480] channel.c: Soft-Hanging up channel 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Result of 'SALES_CALL' is NULL
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Result of 'CHANNEL' is 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Result of 'CONTEXT' is 'DIALPLAN-1'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Result of 'CALL_CONNECTED' is '1'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Result of 'CALL_ATTEMPT' is '4'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Launching 'NoOp'
[Oct 19 17:41:12] VERBOSE[21480] pbx.c:     -- Executing [h@DIALPLAN-1:1] NoOp("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "Sales Call:  Channel: Local/DIALCUSTOMER@DIALPLAN-1-1bad;2  Context: DIALPLAN-1  Call Connected: 1, Dial Status: BUSY, CALL ATTEMPT: 4 ") in new stack
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Result of 'SALES_CALL' is NULL
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Expression result is '0'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Launching 'GotoIf'
[Oct 19 17:41:12] VERBOSE[21480] pbx.c:     -- Executing [h@DIALPLAN-1:2] GotoIf("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "0?LOGHANGUP") in new stack
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Not taking any branch
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Expression result is '0'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Launching 'GotoIf'
[Oct 19 17:41:12] VERBOSE[21480] pbx.c:     -- Executing [h@DIALPLAN-1:3] GotoIf("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "0?ENDCALL") in new stack
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Not taking any branch
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Result of 'DIALSTATUS' is 'BUSY'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Result of 'CALL_CONNECTED' is '1'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Expression result is '0'
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Launching 'GotoIf'
[Oct 19 17:41:12] VERBOSE[21480] pbx.c:     -- Executing [h@DIALPLAN-1:4] GotoIf("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "0?RINGNOANSWER:ENDCALL") in new stack
[Oct 19 17:41:12] VERBOSE[21480] pbx.c:     -- Goto (DIALPLAN-1,h,10)
[Oct 19 17:41:12] DEBUG[21480] pbx.c: Launching 'NoOp'
[Oct 19 17:41:12] VERBOSE[21480] pbx.c:     -- Executing [h@DIALPLAN-1:10] NoOp("Local/DIALCUSTOMER@DIALPLAN-1-1bad;2", "") in new stack
[Oct 19 17:41:12] DEBUG[21480] channel.c: Hanging up channel 'Local/DIALCUSTOMER@DIALPLAN-1-1bad;2'
[Oct 19 17:41:12] DEBUG[21480] cdr_mysql.c: Inserting a CDR record.
[Oct 19 17:41:12] DEBUG[21480] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`duration`,`billsec`,`disposition`,`amaflags`,`userfield`,`uniqueid`) VALUES ('2011-10-19 17:40:52','19414876477','19414876477','DIALCUSTOMER','DIALPLAN-1','Local/DIALCUSTOMER@DIALPLAN-1-1bad;2','SIP/voipms-00006e34','Hangup','20','0','BUSY','3','1909303','1319060452.53104')