[Feb 19 13:37:44] DEBUG[15625]: chan_zap.c:1441 zt_enable_ec: Enabled echo cancellation on channel 1
[Feb 19 13:37:44] DEBUG[15625]: pbx.c:1831 pbx_extension_helper: Launching 'Dial'
    -- Executing [s@fax-in:1] Dial("Zap/1-1", "IAX2/iaxmodem0/s") in new stack
[Feb 19 13:37:44] DEBUG[15625]: rtp.c:1585 ast_rtp_make_compatible: Channel 'IAX2/iaxmodem0-1' has no RTP, not doing anything
[Feb 19 13:37:44] DEBUG[15625]: channel.c:3277 ast_channel_inherit_variables: Not copying variable TRANSFERCAPABILITY.
[Feb 19 13:37:44] DEBUG[15625]: chan_iax2.c:2935 create_addr: prepending 4 to prefs
[Feb 19 13:37:44] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iaxmodem0-1
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iaxmodem0-1
[Feb 19 13:37:44] DEBUG[15430]: chan_iax2.c:10432 iax2_devicestate: Checking device state for device iaxmodem0-1
[Feb 19 13:37:44] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iaxmodem0
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for IAX2/iaxmodem0-1 - state 4 (Invalid)
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iaxmodem0
    -- Called iaxmodem0/s
[Feb 19 13:37:44] DEBUG[15430]: chan_iax2.c:10432 iax2_devicestate: Checking device state for device iaxmodem0
[Feb 19 13:37:44] DEBUG[15430]: chan_iax2.c:10440 iax2_devicestate: iax2_devicestate: Found peer. What's device state of iaxmodem0? addr=16777343, defaddr=0 maxms=0, lastms=0
[Feb 19 13:37:44] DEBUG[15430]: channel.c:1068 channel_find_locked: Avoiding initial deadlock for channel '0x81ba9f0'
[Feb 19 13:37:44] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'IAX2/iaxmodem0-1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for IAX2/iaxmodem0 - state 6 (Ringing)
[Feb 19 13:37:44] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'IAX2/iaxmodem0' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
    -- Call accepted by 127.0.0.1 (format ulaw)
    -- Format for call is ulaw
[Feb 19 13:37:44] DEBUG[15442]: channel.c:2763 set_format: Set channel IAX2/iaxmodem0-1 to write format ulaw
[Feb 19 13:37:44] DEBUG[15442]: channel.c:2763 set_format: Set channel IAX2/iaxmodem0-1 to read format ulaw
    -- IAX2/iaxmodem0-1 is ringing
[Feb 19 13:37:44] DEBUG[15625]: rtp.c:1502 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything
[Feb 19 13:37:44] DEBUG[15625]: chan_zap.c:5019 zt_indicate: Requested indication 3 on channel Zap/1-1
[Feb 19 13:37:44] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1-1
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for Zap/1-1 - state 0 (Unknown)
[Feb 19 13:37:44] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'Zap/1-1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Feb 19 13:37:44] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 6 (Ringing)
[Feb 19 13:37:44] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'Zap/1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Feb 19 13:37:44] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iaxmodem0-1
[Feb 19 13:37:44] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iaxmodem0
    -- IAX2/iaxmodem0-1 answered Zap/1-1
[Feb 19 13:37:44] DEBUG[15625]: rtp.c:1502 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything
[Feb 19 13:37:44] DEBUG[15625]: chan_zap.c:5019 zt_indicate: Requested indication -1 on channel Zap/1-1
[Feb 19 13:37:44] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1
[Feb 19 13:37:44] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1
[Feb 19 13:37:44] DEBUG[15625]: chan_zap.c:2781 zt_answer: Took Zap/1-1 off hook
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iaxmodem0-1
[Feb 19 13:37:44] DEBUG[15430]: chan_iax2.c:10432 iax2_devicestate: Checking device state for device iaxmodem0-1
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for IAX2/iaxmodem0-1 - state 4 (Invalid)
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iaxmodem0
[Feb 19 13:37:44] DEBUG[15430]: chan_iax2.c:10432 iax2_devicestate: Checking device state for device iaxmodem0
[Feb 19 13:37:44] DEBUG[15430]: chan_iax2.c:10440 iax2_devicestate: iax2_devicestate: Found peer. What's device state of iaxmodem0? addr=16777343, defaddr=0 maxms=0, lastms=0
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for IAX2/iaxmodem0 - state 2 (In use)
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1-1
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for Zap/1-1 - state 0 (Unknown)
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1
[Feb 19 13:37:44] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 2 (In use)
[Feb 19 13:37:44] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'IAX2/iaxmodem0-1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Feb 19 13:37:44] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'IAX2/iaxmodem0' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Feb 19 13:37:44] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'Zap/1-1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Feb 19 13:37:44] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'Zap/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Feb 19 13:37:44] DEBUG[15435]: chan_iax2.c:7188 socket_process: Ooh, voice format changed to 4
[Feb 19 13:37:44] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:44] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4596 __zt_exception: Exception on 15, channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:3717 zt_handle_event: Got event Wink/Flash(3) on channel 1 (index 0)
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4373 zt_handle_event: Got wink in weird state 6 on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:37:45] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1

** Repeats from line 90 through 2255 **

[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:4918 my_zt_write: Write returned -1 (Resource temporarily unavailable) on channel 1
[Feb 19 13:38:28] DEBUG[15441]: chan_iax2.c:7527 socket_process: Immediately destroying 1, having received hangup
[Feb 19 13:38:28] DEBUG[15625]: channel.c:3753 ast_generic_bridge: Didn't get a frame from channel: IAX2/iaxmodem0-1
[Feb 19 13:38:28] DEBUG[15625]: channel.c:4078 ast_channel_bridge: Bridge stops bridging channels Zap/1-1 and IAX2/iaxmodem0-1
[Feb 19 13:38:28] DEBUG[15625]: channel.c:1477 ast_hangup: Hanging up channel 'IAX2/iaxmodem0-1'
[Feb 19 13:38:28] DEBUG[15625]: chan_iax2.c:3238 iax2_hangup: We're hanging up IAX2/iaxmodem0-1 now...
[Feb 19 13:38:28] DEBUG[15625]: chan_iax2.c:3254 iax2_hangup: Really destroying IAX2/iaxmodem0-1 now...
    -- Hungup 'IAX2/iaxmodem0-1'
[Feb 19 13:38:28] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iaxmodem0-1
[Feb 19 13:38:28] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iaxmodem0
[Feb 19 13:38:28] DEBUG[15625]: rtp.c:1502 ast_rtp_early_bridge: Channel 'Zap/1-1' has no RTP, not doing anything
[Feb 19 13:38:28] DEBUG[15625]: app_dial.c:1741 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[Feb 19 13:38:28] DEBUG[15625]: pbx.c:2427 __ast_pbx_run: Spawn extension (fax-in,s,1) exited non-zero on 'Zap/1-1'
  == Spawn extension (fax-in, s, 1) exited non-zero on 'Zap/1-1'
[Feb 19 13:38:28] DEBUG[15625]: channel.c:1378 ast_softhangup_nolock: Soft-Hanging up channel 'Zap/1-1'
[Feb 19 13:38:28] DEBUG[15625]: channel.c:1477 ast_hangup: Hanging up channel 'Zap/1-1'
[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:2423 zt_hangup: zt_hangup(Zap/1-1)
[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:2457 zt_hangup: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1
[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:1473 zt_disable_ec: disabled echo cancellation on channel 1
[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:2887 zt_setoption: Set option TDD MODE, value: OFF(0) on Zap/1-1
[Feb 19 13:38:28] DEBUG[15625]: chan_zap.c:1409 update_conf: Updated conferencing on 1, with 0 conference users
    -- Hungup 'Zap/1-1'
[Feb 19 13:38:28] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1-1
[Feb 19 13:38:28] DEBUG[15625]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Zap/1
[Feb 19 13:38:28] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iaxmodem0-1
[Feb 19 13:38:28] DEBUG[15430]: chan_iax2.c:10432 iax2_devicestate: Checking device state for device iaxmodem0-1
[Feb 19 13:38:28] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for IAX2/iaxmodem0-1 - state 4 (Invalid)
[Feb 19 13:38:28] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iaxmodem0
[Feb 19 13:38:28] DEBUG[15430]: chan_iax2.c:10432 iax2_devicestate: Checking device state for device iaxmodem0
[Feb 19 13:38:28] DEBUG[15430]: chan_iax2.c:10440 iax2_devicestate: iax2_devicestate: Found peer. What's device state of iaxmodem0? addr=16777343, defaddr=0 maxms=0, lastms=0
[Feb 19 13:38:28] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for IAX2/iaxmodem0 - state 1 (Not in use)
[Feb 19 13:38:28] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1-1
[Feb 19 13:38:28] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for Zap/1-1 - state 0 (Unknown)
[Feb 19 13:38:28] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Zap - 1
[Feb 19 13:38:28] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for Zap/1 - state 0 (Unknown)
[Feb 19 13:38:28] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'IAX2/iaxmodem0-1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Feb 19 13:38:28] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'IAX2/iaxmodem0' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb 19 13:38:28] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'Zap/1-1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Feb 19 13:38:28] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'Zap/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Feb 19 13:39:28] DEBUG[15440]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/iaxmodem0
[Feb 19 13:39:28] DEBUG[15430]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for IAX2 - iaxmodem0
[Feb 19 13:39:28] DEBUG[15430]: chan_iax2.c:10432 iax2_devicestate: Checking device state for device iaxmodem0
[Feb 19 13:39:28] DEBUG[15430]: chan_iax2.c:10440 iax2_devicestate: iax2_devicestate: Found peer. What's device state of iaxmodem0? addr=16777343, defaddr=0 maxms=0, lastms=0
[Feb 19 13:39:28] DEBUG[15430]: devicestate.c:287 do_state_change: Changing state for IAX2/iaxmodem0 - state 1 (Not in use)
[Feb 19 13:39:28] DEBUG[15450]: app_queue.c:595 handle_statechange: Device 'IAX2/iaxmodem0' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.