-- Executing [150@from-ido-sip:1] Dial("SIP/401-09b2e1e0", "Zap/1/150|20") in new stack
[Jun 7 16:49:40] DEBUG[19535]: chan_zap.c:7818 zt_request: Using channel 1
[Jun 7 16:49:40] DEBUG[19535]: rtp.c:1567 ast_rtp_make_compatible: Channel 'Zap/1-1' has no RTP, not doing anything
[Jun 7 16:49:40] DEBUG[19535]: channel.c:3413 ast_channel_inherit_variables: Not copying variable STACK-from-ido-sip-150-1.
[Jun 7 16:49:40] DEBUG[19535]: channel.c:3413 ast_channel_inherit_variables: Not copying variable SIPCALLID.
[Jun 7 16:49:40] DEBUG[19535]: channel.c:3413 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT.
[Jun 7 16:49:40] DEBUG[19535]: channel.c:3413 ast_channel_inherit_variables: Not copying variable SIPDOMAIN.
[Jun 7 16:49:40] DEBUG[19535]: channel.c:3413 ast_channel_inherit_variables: Not copying variable SIPURI.
-- Requested transfer capability: 0x00 - SPEECH
[Jun 7 16:49:40] DEBUG[19504]: channel.c:1058 channel_find_locked: Avoiding initial deadlock for channel '0x9b328a0'
-- Called 1/150
[Jun 7 16:49:40] DEBUG[19535]: chan_sip.c:6478 transmit_response_with_sdp: Setting framing from config on incoming call
[Jun 7 16:49:40] DEBUG[19535]: rtp.c:2717 ast_rtp_write: Ooh, format changed from unknown to alaw
[Jun 7 16:49:40] DEBUG[19535]: rtp.c:2734 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160
[Jun 7 16:49:40] DEBUG[19506]: chan_zap.c:8957 pri_dchannel: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/1 span 1
-- Zap/1-1 is proceeding passing it to SIP/401-09b2e1e0
[Jun 7 16:49:40] DEBUG[19535]: rtp.c:1492 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything
[Jun 7 16:49:40] DEBUG[19506]: chan_zap.c:1436 zt_enable_ec: No echo cancellation requested
[Jun 7 16:49:40] DEBUG[19504]: channel.c:1058 channel_find_locked: Avoiding initial deadlock for channel '0x9b328a0'
-- Zap/1-1 is ringing
[Jun 7 16:49:40] DEBUG[19535]: rtp.c:1492 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything
[Jun 7 16:49:40] DEBUG[19535]: chan_sip.c:4131 sip_rtp_read: Oooh, format changed to 1
[Jun 7 16:49:40] WARNING[19535]: channel.c:2918 set_format: Unable to find a codec translation path from g723 to alaw
[Jun 7 16:49:40] WARNING[19535]: channel.c:2918 set_format: Unable to find a codec translation path from g723 to alaw
[Jun 7 16:49:40] WARNING[19535]: chan_zap.c:4934 zt_write: Cannot handle frames in 1 format
[Jun 7 16:49:40] WARNING[19535]: app_dial.c:741 wait_for_answer: Unable to forward voice or dtmf
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is ''
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is ''
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 's'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 'from-ido'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 'Zap/1-1'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is ''
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is ''
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is ''
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '2007-06-07 16:49:40'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is ''
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '2007-06-07 16:49:40'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is ''
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '1181220580.7'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is ''
[Jun 7 16:49:40] DEBUG[19535]: channel.c:1727 ast_hangup: Hanging up channel 'Zap/1-1'
[Jun 7 16:49:40] DEBUG[19535]: chan_zap.c:2411 zt_hangup: zt_hangup(Zap/1-1)
[Jun 7 16:49:40] DEBUG[19535]: chan_zap.c:2956 zt_setoption: Set option AUDIO MODE, value: ON(1) on Zap/1-1
[Jun 7 16:49:40] DEBUG[19535]: chan_zap.c:2445 zt_hangup: Hangup: channel: 1 index = 0, normal = 9, callwait = -1, thirdcall = -1
[Jun 7 16:49:40] DEBUG[19535]: chan_zap.c:2599 zt_hangup: Not yet hungup... Calling hangup once with icause, and clearing call
[Jun 7 16:49:40] DEBUG[19535]: chan_zap.c:2873 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/1-1
[Jun 7 16:49:40] DEBUG[19535]: chan_zap.c:1402 update_conf: Updated conferencing on 1, with 0 conference users
[Jun 7 16:49:40] DEBUG[19535]: chan_zap.c:2952 zt_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
-- Hungup 'Zap/1-1'
== Everyone is busy/congested at this time (1:0/0/1)
[Jun 7 16:49:40] DEBUG[19535]: rtp.c:1492 ast_rtp_early_bridge: Channel '<unspecified>' has no RTP, not doing anything
[Jun 7 16:49:40] DEBUG[19535]: app_dial.c:1691 dial_exec_full: Exiting with DIALSTATUS=CHANUNAVAIL.
== Auto fallthrough, channel 'SIP/401-09b2e1e0' status is 'CHANUNAVAIL'
[Jun 7 16:49:40] DEBUG[19535]: channel.c:1514 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/401-09b2e1e0'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '"401" <401>'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '401'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '150'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 'from-ido-sip'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 'SIP/401-09b2e1e0'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 'Zap/1-1'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 'Dial'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 'Zap/1/150|20'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '2007-06-07 16:49:40'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is ''
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '2007-06-07 16:49:40'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '0'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is ''
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is '1181220580.6'
[Jun 7 16:49:40] DEBUG[19535]: pbx.c:1668 pbx_substitute_variables_helper_full: Function result is ''
[Jun 7 16:49:40] DEBUG[19535]: channel.c:1727 ast_hangup: Hanging up channel 'SIP/401-09b2e1e0'
[Jun 7 16:49:40] DEBUG[19535]: chan_sip.c:3346 sip_hangup: Hangup call SIP/401-09b2e1e0, SIP callid 1819216909-101944251@192.168.3.178)
[Jun 7 16:49:40] DEBUG[19508]: chan_sip.c:2120 __sip_ack: Stopping retransmission on '1819216909-101944251@192.168.3.178' of Response 2: Match Found