[Jun 22 12:24:30] VERBOSE[14162] logger.c: -- Executing [7147832205@call-cust-03:14] Dial("SIP/innovative-0907f0b0", "Zap/g5/*7142318220*2205*|10|r") in new stack
[Jun 22 12:24:30] DEBUG[14162] chan_zap.c: Using channel 97
[Jun 22 12:24:30] DEBUG[14162] rtp.c: Channel 'Zap/97-1' has no RTP, not doing anything
[Jun 22 12:24:30] DEBUG[14162] channel.c: Copying hard-transferable variable MONITORED.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Not copying variable CALLFILENAME.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Not copying variable CALLINFO.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Not copying variable CALLTIME.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Not copying variable STIME.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Not copying variable IVR-Exten.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Copying hard-transferable variable CALLINGPRES_SV.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Not copying variable FAX_RX.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Not copying variable LOOKUPBLSTATUS.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Copying hard-transferable variable FROM_DID.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Not copying variable SIPCALLID.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Not copying variable SIPUSERAGENT.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Not copying variable SIPDOMAIN.
[Jun 22 12:24:30] DEBUG[14162] channel.c: Not copying variable SIPURI.
[Jun 22 12:24:30] DEBUG[14162] chan_zap.c: Dialing '*7142318220*2205*'
[Jun 22 12:24:30] DEBUG[14162] chan_zap.c: Deferring dialing...
[Jun 22 12:24:30] DEBUG[14162] devicestate.c: Notification of state change to be queued on device/channel Zap/97-1
[Jun 22 12:24:30] DEBUG[14162] devicestate.c: Notification of state change to be queued on device/channel Zap/97
[Jun 22 12:24:30] VERBOSE[14162] logger.c: -- Called g5/*7142318220*2205*
[Jun 22 12:24:30] DEBUG[14162] channel.c: Driver for channel 'SIP/innovative-0907f0b0' does not support indication 3, emulating it
[Jun 22 12:24:30] DEBUG[14162] channel.c: Set channel SIP/innovative-0907f0b0 to write format slin
[Jun 22 12:24:30] DEBUG[14162] channel.c: Scheduling timer at 160 sample intervals
[Jun 22 12:24:30] DEBUG[14136] devicestate.c: Changing state for SIP/innovative-0907f0b0 - state 4 (Invalid)
[Jun 22 12:24:30] DEBUG[14136] devicestate.c: No provider found, checking channel drivers for SIP - innovative
[Jun 22 12:24:30] DEBUG[14136] chan_sip.c: Checking device state for peer innovative
[Jun 22 12:24:30] DEBUG[14138] app_queue.c: Device 'SIP/innovative-0907f0b0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jun 22 12:24:30] DEBUG[14136] devicestate.c: Changing state for SIP/innovative - state 2 (In use)
[Jun 22 12:24:30] DEBUG[14136] devicestate.c: No provider found, checking channel drivers for SIP - innovative-0907f0b0
[Jun 22 12:24:30] DEBUG[14136] chan_sip.c: Checking device state for peer innovative-0907f0b0
[Jun 22 12:24:30] DEBUG[14138] app_queue.c: Device 'SIP/innovative' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun 22 12:24:30] DEBUG[14162] rtp.c: Ooh, format changed from unknown to ulaw
[Jun 22 12:24:30] DEBUG[14162] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jun 22 12:24:30] DEBUG[14136] devicestate.c: Changing state for SIP/innovative-0907f0b0 - state 4 (Invalid)
[Jun 22 12:24:30] DEBUG[14136] devicestate.c: No provider found, checking channel drivers for SIP - innovative
[Jun 22 12:24:30] DEBUG[14138] app_queue.c: Device 'SIP/innovative-0907f0b0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jun 22 12:24:30] DEBUG[14136] chan_sip.c: Checking device state for peer innovative
[Jun 22 12:24:30] DEBUG[14136] devicestate.c: Changing state for SIP/innovative - state 2 (In use)
[Jun 22 12:24:30] DEBUG[14136] devicestate.c: No provider found, checking channel drivers for Zap - 97-1
[Jun 22 12:24:30] DEBUG[14138] app_queue.c: Device 'SIP/innovative' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun 22 12:24:30] DEBUG[14136] devicestate.c: Changing state for Zap/97-1 - state 0 (Unknown)
[Jun 22 12:24:30] DEBUG[14136] devicestate.c: No provider found, checking channel drivers for Zap - 97
[Jun 22 12:24:30] DEBUG[14138] app_queue.c: Device 'Zap/97-1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jun 22 12:24:30] DEBUG[14136] devicestate.c: Changing state for Zap/97 - state 2 (In use)
[Jun 22 12:24:30] DEBUG[14138] app_queue.c: Device 'Zap/97' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun 22 12:24:30] DEBUG[14157] chan_sip.c: = Found Their Call ID: 5958d43628d284da39434d240c136d0c@64.2.142.30 Their Tag as501c7863 Our tag: as24dbbeaf
[Jun 22 12:24:30] DEBUG[14157] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jun 22 12:24:30] DEBUG[14157] chan_sip.c: Stopping retransmission on '5958d43628d284da39434d240c136d0c@64.2.142.30' of Response 102: Match Found
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] chan_zap.c: Exception on 110, channel 97
[Jun 22 12:24:30] DEBUG[14162] chan_zap.c: Got event Wink/Flash(3) on channel 97 (index 0)
[Jun 22 12:24:30] DEBUG[14162] chan_zap.c: Ignoring wink on channel 97
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:30] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] chan_zap.c: Exception on 110, channel 97
[Jun 22 12:24:31] DEBUG[14162] chan_zap.c: Got event Hook Transition Complete(12) on channel 97 (index 0)
[Jun 22 12:24:31] DEBUG[14162] chan_zap.c: Sent deferred digit string: T*7142318220*2205
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:31] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:32] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:33] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:34] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:35] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:36] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] chan_zap.c: Exception on 110, channel 97
[Jun 22 12:24:37] DEBUG[14162] chan_zap.c: Got event Dial Complete(9) on channel 97 (index 0)
[Jun 22 12:24:37] DEBUG[14162] chan_zap.c: Enabled echo cancellation on channel 97
[Jun 22 12:24:37] DEBUG[14162] chan_zap.c: Engaged echo training on channel 97
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:37] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:38] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=216)
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Exception on 110, channel 97
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Got event Ring/Answered(2) on channel 97 (index 0)
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Line answered
[Jun 22 12:24:39] DEBUG[14162] devicestate.c: Notification of state change to be queued on device/channel Zap/97-1
[Jun 22 12:24:39] DEBUG[14136] devicestate.c: No provider found, checking channel drivers for Zap - 97-1
[Jun 22 12:24:39] DEBUG[14162] devicestate.c: Notification of state change to be queued on device/channel Zap/97
[Jun 22 12:24:39] VERBOSE[14162] logger.c: -- Zap/97-1 answered SIP/innovative-0907f0b0
[Jun 22 12:24:39] DEBUG[14162] rtp.c: Channel 'Zap/97-1' has no RTP, not doing anything
[Jun 22 12:24:39] DEBUG[14162] channel.c: Set channel SIP/innovative-0907f0b0 to write format ulaw
[Jun 22 12:24:39] DEBUG[14162] channel.c: Scheduling timer at 0 sample intervals
[Jun 22 12:24:39] DEBUG[14136] devicestate.c: Changing state for Zap/97-1 - state 0 (Unknown)
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Requested indication 20 on channel Zap/97-1
[Jun 22 12:24:39] DEBUG[14136] devicestate.c: No provider found, checking channel drivers for Zap - 97
[Jun 22 12:24:39] DEBUG[14138] app_queue.c: Device 'Zap/97-1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jun 22 12:24:39] DEBUG[14136] devicestate.c: Changing state for Zap/97 - state 2 (In use)
[Jun 22 12:24:39] DEBUG[14138] app_queue.c: Device 'Zap/97' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:39] DEBUG[14162] chan_zap.c: Dropping frame since I'm still dialing on Zap/97-1...
[Jun 22 12:24:40] DEBUG[14162] chan_zap.c: Exception on 110, channel 97
[Jun 22 12:24:40] DEBUG[14162] chan_zap.c: Got event Dial Complete(9) on channel 97 (index 0)
[Jun 22 12:24:40] DEBUG[14162] chan_zap.c: Echo cancellation already on
[Jun 22 12:24:40] DEBUG[14162] rtp.c: Difference is 5288, ms is 681
[Jun 22 12:24:52] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:52] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:52] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:52] DEBUG[14162] rtp.c: Sending dtmf: 49 (1), at 64.2.142.30
[Jun 22 12:24:52] DTMF[14162] channel.c: DTMF begin '1' received on SIP/innovative-0907f0b0
[Jun 22 12:24:52] DTMF[14162] channel.c: DTMF begin passthrough '1' on SIP/innovative-0907f0b0
[Jun 22 12:24:52] DEBUG[14162] chan_zap.c: Started VLDTMF digit '1'
[Jun 22 12:24:52] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:52] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:52] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:52] DEBUG[14162] rtp.c: Sending dtmf: 49 (1), at 64.2.142.30
[Jun 22 12:24:52] DTMF[14162] channel.c: DTMF end '1' received on SIP/innovative-0907f0b0, duration 100 ms
[Jun 22 12:24:52] DTMF[14162] channel.c: DTMF end accepted with begin '1' on SIP/innovative-0907f0b0
[Jun 22 12:24:52] DTMF[14162] channel.c: DTMF end passthrough '1' on SIP/innovative-0907f0b0
[Jun 22 12:24:52] DEBUG[14162] chan_zap.c: Ending VLDTMF digit '1'
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:53] DEBUG[14162] rtp.c: Sending dtmf: 49 (1), at 64.2.142.30
[Jun 22 12:24:53] DTMF[14162] channel.c: DTMF begin '1' received on SIP/innovative-0907f0b0
[Jun 22 12:24:53] DTMF[14162] channel.c: DTMF begin passthrough '1' on SIP/innovative-0907f0b0
[Jun 22 12:24:53] DEBUG[14162] chan_zap.c: Started VLDTMF digit '1'
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:53] DEBUG[14162] rtp.c: Sending dtmf: 49 (1), at 64.2.142.30
[Jun 22 12:24:53] DTMF[14162] channel.c: DTMF end '1' received on SIP/innovative-0907f0b0, duration 100 ms
[Jun 22 12:24:53] DTMF[14162] channel.c: DTMF end accepted with begin '1' on SIP/innovative-0907f0b0
[Jun 22 12:24:53] DTMF[14162] channel.c: DTMF end passthrough '1' on SIP/innovative-0907f0b0
[Jun 22 12:24:53] DEBUG[14162] chan_zap.c: Ending VLDTMF digit '1'
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:53] DEBUG[14162] rtp.c: Sending dtmf: 49 (1), at 64.2.142.30
[Jun 22 12:24:53] DTMF[14162] channel.c: DTMF begin '1' received on SIP/innovative-0907f0b0
[Jun 22 12:24:53] DTMF[14162] channel.c: DTMF begin passthrough '1' on SIP/innovative-0907f0b0
[Jun 22 12:24:53] DEBUG[14162] chan_zap.c: Started VLDTMF digit '1'
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:53] DEBUG[14162] rtp.c: Sending dtmf: 49 (1), at 64.2.142.30
[Jun 22 12:24:53] DTMF[14162] channel.c: DTMF end '1' received on SIP/innovative-0907f0b0, duration 100 ms
[Jun 22 12:24:53] DTMF[14162] channel.c: DTMF end accepted with begin '1' on SIP/innovative-0907f0b0
[Jun 22 12:24:53] DTMF[14162] channel.c: DTMF end passthrough '1' on SIP/innovative-0907f0b0
[Jun 22 12:24:53] DEBUG[14162] chan_zap.c: Ending VLDTMF digit '1'
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:53] DEBUG[14162] rtp.c: - RTP 2833 Event: 00000001 (len = 4)
[Jun 22 12:24:57] DEBUG[14157] chan_sip.c: = Found Their Call ID: 5958d43628d284da39434d240c136d0c@64.2.142.30 Their Tag as501c7863 Our tag: as24dbbeaf
[Jun 22 12:24:57] DEBUG[14157] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Jun 22 12:24:57] DEBUG[14157] chan_sip.c: Setting SIP_ALREADYGONE on dialog 5958d43628d284da39434d240c136d0c@64.2.142.30
[Jun 22 12:24:57] DEBUG[14157] chan_sip.c: Received bye, issuing owner hangup
[Jun 22 12:24:57] DEBUG[14162] channel.c: Didn't get a frame from channel: SIP/innovative-0907f0b0
[Jun 22 12:24:57] DEBUG[14162] chan_zap.c: Requested indication 20 on channel Zap/97-1
[Jun 22 12:24:57] DEBUG[14162] channel.c: Bridge stops bridging channels SIP/innovative-0907f0b0 and Zap/97-1
[Jun 22 12:24:57] DEBUG[14162] channel.c: Hanging up channel 'Zap/97-1'
[Jun 22 12:24:57] DEBUG[14162] chan_zap.c: zt_hangup(Zap/97-1)
[Jun 22 12:24:57] DEBUG[14162] chan_zap.c: Hangup: channel: 97 index = 0, normal = 110, callwait = -1, thirdcall = -1
[Jun 22 12:24:57] DEBUG[14162] chan_zap.c: disabled echo cancellation on channel 97
[Jun 22 12:24:57] DEBUG[14162] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/97-1
[Jun 22 12:24:57] DEBUG[14162] chan_zap.c: Updated conferencing on 97, with 0 conference users
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Hungup 'Zap/97-1'
[Jun 22 12:24:57] DEBUG[14162] devicestate.c: Notification of state change to be queued on device/channel Zap/97-1
[Jun 22 12:24:57] DEBUG[14162] devicestate.c: Notification of state change to be queued on device/channel Zap/97
[Jun 22 12:24:57] DEBUG[14162] rtp.c: Channel '' has no RTP, not doing anything
[Jun 22 12:24:57] DEBUG[14136] devicestate.c: No provider found, checking channel drivers for Zap - 97-1
[Jun 22 12:24:57] DEBUG[14162] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jun 22 12:24:57] DEBUG[14136] devicestate.c: Changing state for Zap/97-1 - state 0 (Unknown)
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Spawn extension (call-cust-03,7147832205,14) exited non-zero on 'SIP/innovative-0907f0b0'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: == Spawn extension (call-cust-03, 7147832205, 14) exited non-zero on 'SIP/innovative-0907f0b0'
[Jun 22 12:24:57] DEBUG[14162] channel.c: Soft-Hanging up channel 'SIP/innovative-0907f0b0'
[Jun 22 12:24:57] DEBUG[14136] devicestate.c: No provider found, checking channel drivers for Zap - 97
[Jun 22 12:24:57] DEBUG[14138] app_queue.c: Device 'Zap/97-1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'Verbose'
[Jun 22 12:24:57] DEBUG[14136] devicestate.c: Changing state for Zap/97 - state 0 (Unknown)
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [h@call-cust-03:1] Verbose("SIP/innovative-0907f0b0", "1|[7147832205-inn] Adline detected Caller hangup h ") in new stack
[Jun 22 12:24:57] VERBOSE[14162] logger.c: [7147832205-inn] Adline detected Caller hangup h
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'Goto'
[Jun 22 12:24:57] DEBUG[14138] app_queue.c: Device 'Zap/97' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [h@call-cust-03:2] Goto("SIP/innovative-0907f0b0", "calldone|1") in new stack
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Goto (call-cust-03,calldone,1)
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'Set'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [calldone@call-cust-03:1] Set("SIP/innovative-0907f0b0", "ETIME=1214162697") in new stack
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Expression result is '27'
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'Set'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [calldone@call-cust-03:2] Set("SIP/innovative-0907f0b0", "DUR=27") in new stack
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'Gosub'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [calldone@call-cust-03:3] Gosub("SIP/innovative-0907f0b0", "updatedur|1") in new stack
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Expression result is '0'
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'GotoIf'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [updatedur@call-cust-03:1] GotoIf("SIP/innovative-0907f0b0", "0?exit|1") in new stack
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Not taking any branch
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'Verbose'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [updatedur@call-cust-03:2] Verbose("SIP/innovative-0907f0b0", "1|[7147832205-inn] Updating Duration in DNISLookUP for 7147832205 with 27 seconds") in new stack
[Jun 22 12:24:57] VERBOSE[14162] logger.c: [7147832205-inn] Updating Duration in DNISLookUP for 7147832205 with 27 seconds
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'MYSQL'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [updatedur@call-cust-03:3] MYSQL("SIP/innovative-0907f0b0", "Connect connid localhost root passw0rd dax") in new stack
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'MYSQL'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [updatedur@call-cust-03:4] MYSQL("SIP/innovative-0907f0b0", "Query resultid 1 UPDATE dnislookup SET duration=duration+27 WHERE dnis=7147832205") in new stack
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'MYSQL'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [updatedur@call-cust-03:5] MYSQL("SIP/innovative-0907f0b0", "Clear ") in new stack
[Jun 22 12:24:57] WARNING[14162] app_addon_sql_mysql.c: Identifier 0, identifier_type 2 not found in identifier list
[Jun 22 12:24:57] WARNING[14162] app_addon_sql_mysql.c: Invalid result identifier 0 passed in aMYSQL_clear
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'MYSQL'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [updatedur@call-cust-03:6] MYSQL("SIP/innovative-0907f0b0", "Disconnect 1") in new stack
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'Set'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [updatedur@call-cust-03:7] Set("SIP/innovative-0907f0b0", "CALLLOGED=Y") in new stack
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'Return'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [updatedur@call-cust-03:8] Return("SIP/innovative-0907f0b0", "") in new stack
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Function result is '03:24:57'
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'Verbose'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [calldone@call-cust-03:4] Verbose("SIP/innovative-0907f0b0", "1|[7147832205-inn] Exit START:[12:24] END:[03:24:57] DUR:[27] ") in new stack
[Jun 22 12:24:57] VERBOSE[14162] logger.c: [7147832205-inn] Exit START:[12:24] END:[03:24:57] DUR:[27]
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Launching 'Hangup'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: -- Executing [calldone@call-cust-03:5] Hangup("SIP/innovative-0907f0b0", "") in new stack
[Jun 22 12:24:57] DEBUG[14162] pbx.c: Spawn extension (call-cust-03,calldone,5) exited non-zero on 'SIP/innovative-0907f0b0'
[Jun 22 12:24:57] VERBOSE[14162] logger.c: == Spawn extension (call-cust-03, calldone, 5) exited non-zero on 'SIP/innovative-0907f0b0'
[Jun 22 12:24:57] DEBUG[14162] channel.c: Hanging up channel 'SIP/innovative-0907f0b0'
[Jun 22 12:24:57] DEBUG[14162] chan_sip.c: Hangup call SIP/innovative-0907f0b0, SIP callid 5958d43628d284da39434d240c136d0c@64.2.142.30)
[Jun 22 12:24:57] DEBUG[14162] res_monitor.c: monitor executing ( nice -n 19 soxmix "/var/spool/asterisk/monitor/7147832205-7142318220--in.wav" "/var/spool/asterisk/monitor/7147832205-7142318220--out.wav" "/var/spool/asterisk/monitor/7147832205-7142318220-.wav" && rm -f "/var/spool/asterisk/monitor/7147832205-7142318220--"* ) &
[Jun 22 12:24:57] VERBOSE[14157] logger.c: Really destroying SIP dialog '5958d43628d284da39434d240c136d0c@64.2.142.30' Method: BYE
[Jun 22 12:24:57] DEBUG[14162] devicestate.c: Notification of state change to be queued on device/channel SIP/innovative-0907f0b0
[Jun 22 12:24:57] DEBUG[14162] devicestate.c: Notification of state change to be queued on device/channel SIP/innovative
[Jun 22 12:24:57] DEBUG[14136] devicestate.c: No provider found, checking channel drivers for SIP - innovative-0907f0b0
[Jun 22 12:24:57] DEBUG[14136] chan_sip.c: Checking device state for peer innovative-0907f0b0
[Jun 22 12:24:57] DEBUG[14162] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Jun 22 12:24:57] DEBUG[14162] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2008-06-22 12:24:30','\"Cell Phone CA\" <7142318220>','7142318220','7147832205','call-cust-03', 'SIP/innovative-0907f0b0','Zap/97-1','Dial','Zap/g5/*7142318220*2205*|10|r',27,27,'ANSWERED',3,'7147832205')
[Jun 22 12:24:57] DEBUG[14136] devicestate.c: Changing state for SIP/innovative-0907f0b0 - state 4 (Invalid)
[Jun 22 12:24:57] DEBUG[14136] devicestate.c: No provider found, checking channel drivers for SIP - innovative
[Jun 22 12:24:57] DEBUG[14138] app_queue.c: Device 'SIP/innovative-0907f0b0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jun 22 12:24:57] DEBUG[14136] chan_sip.c: Checking device state for peer innovative
[Jun 22 12:24:57] DEBUG[14136] devicestate.c: Changing state for SIP/innovative - state 1 (Not in use)
[Jun 22 12:24:57] DEBUG[14138] app_queue.c: Device 'SIP/innovative' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jun 22 12:24:57] DEBUG[14154] chan_zap.c: Monitor doohicky got event On hook on channel 97
[Jun 22 12:24:57] DEBUG[14154] chan_zap.c: disabled echo cancellation on channel 97
[Jun 22 12:25:13] DEBUG[14157] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun 22 12:25:13] DEBUG[14157] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun 22 12:25:13] DEBUG[14157] chan_sip.c: = No match Their Call ID: 6e6d4a20706c4a5e3cd03f8a4128edf2@67.154.128.86 Their Tag Our tag: as34ba4cc5
[Jun 22 12:25:13] DEBUG[14157] chan_sip.c: = Found Their Call ID: 0b09e6db6a315b032d61eebf6b7bfec2@67.154.128.86 Their Tag Our tag: as673ddf94
[Jun 22 12:25:13] DEBUG[14157] chan_sip.c: Stopping retransmission on '0b09e6db6a315b032d61eebf6b7bfec2@67.154.128.86' of Request 102: Match Found
[Jun 22 12:25:13] DEBUG[14157] chan_sip.c: = Found Their Call ID: 6e6d4a20706c4a5e3cd03f8a4128edf2@67.154.128.86 Their Tag Our tag: as34ba4cc5
[Jun 22 12:25:13] DEBUG[14157] chan_sip.c: Stopping retransmission on '6e6d4a20706c4a5e3cd03f8a4128edf2@67.154.128.86' of Request 102: Match Found
[Jun 22 12:25:13] VERBOSE[14157] logger.c: Really destroying SIP dialog '6e6d4a20706c4a5e3cd03f8a4128edf2@67.154.128.86' Method: OPTIONS
[Jun 22 12:25:13] VERBOSE[14157] logger.c: Really destroying SIP dialog '0b09e6db6a315b032d61eebf6b7bfec2@67.154.128.86' Method: OPTIONS