[Jun 19 14:11:39] VERBOSE[11890] logger.c: -- Called g5/*7142318220*2205*
[Jun 19 14:11:39] DEBUG[11272] 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 19 14:11:39] DEBUG[11270] devicestate.c: No provider found, checking channel drivers for Zap - 97
[Jun 19 14:11:39] DEBUG[11270] devicestate.c: Changing state for Zap/97 - state 2 (In use)
[Jun 19 14:11:39] DEBUG[11272] 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 19 14:11:39] DEBUG[11890] chan_zap.c: Exception on 110, channel 97
[Jun 19 14:11:39] DEBUG[11890] chan_zap.c: Got event Wink/Flash(3) on channel 97 (index 0)
[Jun 19 14:11:39] DEBUG[11890] chan_zap.c: Ignoring wink on channel 97
[Jun 19 14:11:39] DEBUG[11890] chan_zap.c: Exception on 110, channel 97
[Jun 19 14:11:39] DEBUG[11890] chan_zap.c: Got event Hook Transition Complete(12) on channel 97 (index 0)
[Jun 19 14:11:39] DEBUG[11890] chan_zap.c: Sent deferred digit string: T*7142318220*2205
[Jun 19 14:11:40] DEBUG[11291] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun 19 14:11:40] DEBUG[11291] chan_sip.c: = Found Their Call ID: 4401bc5a65d71dfa756266ea3b295720@67.154.128.86 Their Tag Our tag: as0c32620c
[Jun 19 14:11:40] DEBUG[11291] chan_sip.c: Stopping retransmission on '4401bc5a65d71dfa756266ea3b295720@67.154.128.86' of Request 102: Match Found
[Jun 19 14:11:40] VERBOSE[11291] logger.c: Really destroying SIP dialog '4401bc5a65d71dfa756266ea3b295720@67.154.128.86' Method: OPTIONS
[Jun 19 14:11:40] DEBUG[11291] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun 19 14:11:40] DEBUG[11291] chan_sip.c: = Found Their Call ID: 5bcf60b12412f5354c9fe4375f898dae@67.154.128.86 Their Tag Our tag: as5bca62f4
[Jun 19 14:11:40] DEBUG[11291] chan_sip.c: Stopping retransmission on '5bcf60b12412f5354c9fe4375f898dae@67.154.128.86' of Request 102: Match Found
[Jun 19 14:11:40] VERBOSE[11291] logger.c: Really destroying SIP dialog '5bcf60b12412f5354c9fe4375f898dae@67.154.128.86' Method: OPTIONS
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun 19 14:11:43] DEBUG[11890] chan_zap.c: Exception on 110, channel 97
[Jun 19 14:11:43] DEBUG[11890] chan_zap.c: Got event Dial Complete(9) on channel 97 (index 0)
[Jun 19 14:11:43] DEBUG[11890] chan_zap.c: Enabled echo cancellation on channel 97
[Jun 19 14:11:43] DEBUG[11890] chan_zap.c: Engaged echo training on channel 97
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: = No match Their Call ID: 1621a12e0a54b3544e8591ce3cff5aa3@67.154.128.86 Their Tag Our tag: as303c1722
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: = Found Their Call ID: 78ecb43e41ae291314a66bb72616f3e9@67.154.128.86 Their Tag Our tag: as4a0a2418
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: Stopping retransmission on '78ecb43e41ae291314a66bb72616f3e9@67.154.128.86' of Request 102: Match Found
[Jun 19 14:11:43] VERBOSE[11291] logger.c: Really destroying SIP dialog '78ecb43e41ae291314a66bb72616f3e9@67.154.128.86' Method: OPTIONS
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: = Found Their Call ID: 1621a12e0a54b3544e8591ce3cff5aa3@67.154.128.86 Their Tag Our tag: as303c1722
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: Stopping retransmission on '1621a12e0a54b3544e8591ce3cff5aa3@67.154.128.86' of Request 102: Match Found
[Jun 19 14:11:43] VERBOSE[11291] logger.c: Really destroying SIP dialog '1621a12e0a54b3544e8591ce3cff5aa3@67.154.128.86' Method: OPTIONS
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: = No match Their Call ID: 34dfc0477c8673fa71f91ede4dc381d2@67.154.128.86 Their Tag Our tag: as47e61085
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: = No match Their Call ID: 263fc5dd7e76684f13a2b7871fd51993@67.154.128.86 Their Tag Our tag: as71615b45
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: = Found Their Call ID: 3a8e9c6d4aa3917857953d35637d676a@67.154.128.86 Their Tag Our tag: as50baf0a1
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: Stopping retransmission on '3a8e9c6d4aa3917857953d35637d676a@67.154.128.86' of Request 102: Match Found
[Jun 19 14:11:43] VERBOSE[11291] logger.c: Really destroying SIP dialog '3a8e9c6d4aa3917857953d35637d676a@67.154.128.86' Method: OPTIONS
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: = No match Their Call ID: 34dfc0477c8673fa71f91ede4dc381d2@67.154.128.86 Their Tag Our tag: as47e61085
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: = Found Their Call ID: 263fc5dd7e76684f13a2b7871fd51993@67.154.128.86 Their Tag Our tag: as71615b45
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: Stopping retransmission on '263fc5dd7e76684f13a2b7871fd51993@67.154.128.86' of Request 102: Match Found
[Jun 19 14:11:43] VERBOSE[11291] logger.c: Really destroying SIP dialog '263fc5dd7e76684f13a2b7871fd51993@67.154.128.86' Method: OPTIONS
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: = Found Their Call ID: 34dfc0477c8673fa71f91ede4dc381d2@67.154.128.86 Their Tag Our tag: as47e61085
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: Stopping retransmission on '34dfc0477c8673fa71f91ede4dc381d2@67.154.128.86' of Request 102: Match Found
[Jun 19 14:11:43] VERBOSE[11291] logger.c: Really destroying SIP dialog '34dfc0477c8673fa71f91ede4dc381d2@67.154.128.86' Method: OPTIONS
[Jun 19 14:11:43] DEBUG[11291] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP)
[Jun 19 14:11:44] DEBUG[11291] chan_sip.c: = Found Their Call ID: 5208f50a5f2305af7dc9ff6f47d42387@67.154.128.86 Their Tag Our tag: as75448b79
[Jun 19 14:11:44] DEBUG[11291] chan_sip.c: Stopping retransmission on '5208f50a5f2305af7dc9ff6f47d42387@67.154.128.86' of Request 102: Match Found
[Jun 19 14:11:44] VERBOSE[11291] logger.c: Really destroying SIP dialog '5208f50a5f2305af7dc9ff6f47d42387@67.154.128.86' Method: OPTIONS
[Jun 19 14:11:45] DEBUG[11890] chan_zap.c: Exception on 110, channel 97
[Jun 19 14:11:45] DEBUG[11890] chan_zap.c: Got event Dial Complete(9) on channel 97 (index 0)
[Jun 19 14:11:45] DEBUG[11890] chan_zap.c: Echo cancellation already on
[Jun 19 14:11:45] DEBUG[11890] devicestate.c: Notification of state change to be queued on device/channel Zap/97-1
[Jun 19 14:11:45] DEBUG[11890] devicestate.c: Notification of state change to be queued on device/channel Zap/97
[Jun 19 14:11:45] DEBUG[11270] devicestate.c: No provider found, checking channel drivers for Zap - 97-1
[Jun 19 14:11:45] DEBUG[11270] devicestate.c: Changing state for Zap/97-1 - state 0 (Unknown)
[Jun 19 14:11:45] DEBUG[11272] 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 19 14:11:45] DEBUG[11270] devicestate.c: No provider found, checking channel drivers for Zap - 97
[Jun 19 14:11:45] DEBUG[11270] devicestate.c: Changing state for Zap/97 - state 6 (Ringing)
[Jun 19 14:11:45] DEBUG[11272] app_queue.c: Device 'Zap/97' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[Jun 19 14:11:49] DEBUG[11890] chan_zap.c: Exception on 110, channel 97
[Jun 19 14:11:49] DEBUG[11890] chan_zap.c: Got event Ring/Answered(2) on channel 97 (index 0)
[Jun 19 14:11:49] DEBUG[11890] chan_zap.c: Line answered
[Jun 19 14:11:49] DEBUG[11890] devicestate.c: Notification of state change to be queued on device/channel Zap/97-1
[Jun 19 14:11:49] DEBUG[11890] devicestate.c: Notification of state change to be queued on device/channel Zap/97
[Jun 19 14:11:49] DEBUG[11270] devicestate.c: No provider found, checking channel drivers for Zap - 97-1
[Jun 19 14:11:49] DEBUG[11270] devicestate.c: Changing state for Zap/97-1 - state 0 (Unknown)
[Jun 19 14:11:49] VERBOSE[11890] logger.c: -- Zap/97-1 answered SIP/innovative-b7d00468
[Jun 19 14:11:49] DEBUG[11272] 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 19 14:11:49] DEBUG[11270] devicestate.c: No provider found, checking channel drivers for Zap - 97
[Jun 19 14:11:49] DEBUG[11890] rtp.c: Channel 'Zap/97-1' has no RTP, not doing anything
[Jun 19 14:11:49] DEBUG[11270] channel.c: Avoiding initial deadlock for channel '0x9a5c288'
[Jun 19 14:11:49] DEBUG[11890] devicestate.c: Notification of state change to be queued on device/channel SIP/innovative-b7d00468
[Jun 19 14:11:49] DEBUG[11890] devicestate.c: Notification of state change to be queued on device/channel SIP/innovative
[Jun 19 14:11:49] DEBUG[11890] chan_sip.c: SIP answering channel: SIP/innovative-b7d00468
[Jun 19 14:11:49] DEBUG[11890] chan_sip.c: Setting framing from config on incoming call
[Jun 19 14:11:49] DEBUG[11890] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True
[Jun 19 14:11:49] DEBUG[11890] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Jun 19 14:11:49] DEBUG[11890] chan_sip.c: -- Done with adding codecs to SDP
[Jun 19 14:11:49] DEBUG[11890] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=221)
[Jun 19 14:11:49] DEBUG[11890] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Jun 19 14:11:49] DEBUG[11890] chan_zap.c: Requested indication 20 on channel Zap/97-1
[Jun 19 14:11:49] DEBUG[11890] rtp.c: Ooh, format changed from unknown to ulaw
[Jun 19 14:11:49] DEBUG[11890] rtp.c: Created smoother: format: 4 ms: 20 len: 160
[Jun 19 14:11:49] DEBUG[11270] devicestate.c: Changing state for Zap/97 - state 2 (In use)
[Jun 19 14:11:49] DEBUG[11272] 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 19 14:11:49] DEBUG[11270] devicestate.c: No provider found, checking channel drivers for SIP - innovative-b7d00468
[Jun 19 14:11:49] DEBUG[11270] chan_sip.c: Checking device state for peer innovative-b7d00468
[Jun 19 14:11:49] DEBUG[11270] devicestate.c: Changing state for SIP/innovative-b7d00468 - state 4 (Invalid)
[Jun 19 14:11:49] DEBUG[11270] devicestate.c: No provider found, checking channel drivers for SIP - innovative
[Jun 19 14:11:49] DEBUG[11272] app_queue.c: Device 'SIP/innovative-b7d00468' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jun 19 14:11:49] DEBUG[11270] chan_sip.c: Checking device state for peer innovative
[Jun 19 14:11:49] DEBUG[11270] devicestate.c: Changing state for SIP/innovative - state 2 (In use)
[Jun 19 14:11:49] DEBUG[11272] 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 19 14:11:49] DEBUG[11291] chan_sip.c: = Found Their Call ID: 015d297d15a0bd397429c4a70ba8660e@64.2.142.30 Their Tag as7e7b85ee Our tag: as5836a272
[Jun 19 14:11:49] DEBUG[11291] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Jun 19 14:11:49] DEBUG[11291] chan_sip.c: Stopping retransmission on '015d297d15a0bd397429c4a70ba8660e@64.2.142.30' of Response 102: Match Found
[Jun 19 14:11:54] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:54] DEBUG[11890] rtp.c: Sending dtmf: 42 (*), at 64.2.142.30
[Jun 19 14:11:54] DEBUG[11890] chan_zap.c: Started VLDTMF digit '*'
[Jun 19 14:11:54] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:54] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:54] DEBUG[11890] rtp.c: Sending dtmf: 42 (*), at 64.2.142.30
[Jun 19 14:11:54] DEBUG[11890] chan_zap.c: Ending VLDTMF digit '*'
[Jun 19 14:11:54] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:54] DEBUG[11890] rtp.c: Sending dtmf: 42 (*), at 64.2.142.30
[Jun 19 14:11:54] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:54] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:56] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:56] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:56] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:56] DEBUG[11890] rtp.c: Sending dtmf: 42 (*), at 64.2.142.30
[Jun 19 14:11:56] DEBUG[11890] chan_zap.c: Started VLDTMF digit '*'
[Jun 19 14:11:56] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:56] DEBUG[11890] rtp.c: Sending dtmf: 42 (*), at 64.2.142.30
[Jun 19 14:11:56] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:56] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:56] DEBUG[11890] chan_zap.c: Ending VLDTMF digit '*'
[Jun 19 14:11:56] DEBUG[11890] rtp.c: Difference is 800, ms is 120
[Jun 19 14:11:57] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:57] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:57] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:57] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:57] DEBUG[11890] rtp.c: Sending dtmf: 42 (*), at 64.2.142.30
[Jun 19 14:11:57] DEBUG[11890] chan_zap.c: Started VLDTMF digit '*'
[Jun 19 14:11:57] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:57] DEBUG[11890] rtp.c: - RTP 2833 Event: 0000000a (len = 4)
[Jun 19 14:11:57] DEBUG[11890] chan_zap.c: Ending VLDTMF digit '*'
[Jun 19 14:11:57] DEBUG[11890] rtp.c: Difference is 960, ms is 140
[Jun 19 14:12:04] DEBUG[11291] chan_sip.c: = Found Their Call ID: 015d297d15a0bd397429c4a70ba8660e@64.2.142.30 Their Tag as7e7b85ee Our tag: as5836a272
[Jun 19 14:12:04] DEBUG[11291] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Jun 19 14:12:04] DEBUG[11291] chan_sip.c: Setting SIP_ALREADYGONE on dialog 015d297d15a0bd397429c4a70ba8660e@64.2.142.30
[Jun 19 14:12:04] DEBUG[11291] chan_sip.c: Received bye, issuing owner hangup
[Jun 19 14:12:04] DEBUG[11890] channel.c: Didn't get a frame from channel: SIP/innovative-b7d00468
[Jun 19 14:12:04] DEBUG[11890] chan_zap.c: Requested indication 20 on channel Zap/97-1
[Jun 19 14:12:04] DEBUG[11890] channel.c: Bridge stops bridging channels SIP/innovative-b7d00468 and Zap/97-1
[Jun 19 14:12:04] DEBUG[11890] channel.c: Hanging up channel 'Zap/97-1'
[Jun 19 14:12:04] DEBUG[11890] chan_zap.c: zt_hangup(Zap/97-1)
[Jun 19 14:12:04] DEBUG[11890] chan_zap.c: Hangup: channel: 97 index = 0, normal = 110, callwait = -1, thirdcall = -1
[Jun 19 14:12:04] DEBUG[11890] chan_zap.c: disabled echo cancellation on channel 97
[Jun 19 14:12:04] DEBUG[11890] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/97-1
[Jun 19 14:12:04] DEBUG[11890] chan_zap.c: Updated conferencing on 97, with 0 conference users
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Hungup 'Zap/97-1'
[Jun 19 14:12:04] DEBUG[11890] devicestate.c: Notification of state change to be queued on device/channel Zap/97-1
[Jun 19 14:12:04] DEBUG[11890] devicestate.c: Notification of state change to be queued on device/channel Zap/97
[Jun 19 14:12:04] DEBUG[11270] devicestate.c: No provider found, checking channel drivers for Zap - 97-1
[Jun 19 14:12:04] DEBUG[11890] rtp.c: Channel '' has no RTP, not doing anything
[Jun 19 14:12:04] DEBUG[11270] devicestate.c: Changing state for Zap/97-1 - state 0 (Unknown)
[Jun 19 14:12:04] DEBUG[11890] app_dial.c: Exiting with DIALSTATUS=ANSWER.
[Jun 19 14:12:04] DEBUG[11270] devicestate.c: No provider found, checking channel drivers for Zap - 97
[Jun 19 14:12:04] DEBUG[11270] devicestate.c: Changing state for Zap/97 - state 0 (Unknown)
[Jun 19 14:12:04] DEBUG[11272] 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 19 14:12:04] DEBUG[11272] 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 19 14:12:04] DEBUG[11890] pbx.c: Spawn extension (call-cust-03,7147832205,14) exited non-zero on 'SIP/innovative-b7d00468'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: == Spawn extension (call-cust-03, 7147832205, 14) exited non-zero on 'SIP/innovative-b7d00468'
[Jun 19 14:12:04] DEBUG[11890] channel.c: Soft-Hanging up channel 'SIP/innovative-b7d00468'
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'Verbose'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [h@call-cust-03:1] Verbose("SIP/innovative-b7d00468", "1|[7147832205-inn] Adline detected Caller hangup h ") in new stack
[Jun 19 14:12:04] VERBOSE[11890] logger.c: [7147832205-inn] Adline detected Caller hangup h
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'Goto'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [h@call-cust-03:2] Goto("SIP/innovative-b7d00468", "calldone|1") in new stack
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Goto (call-cust-03,calldone,1)
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'Set'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [calldone@call-cust-03:1] Set("SIP/innovative-b7d00468", "ETIME=1213909924") in new stack
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Expression result is '32'
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'Set'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [calldone@call-cust-03:2] Set("SIP/innovative-b7d00468", "DUR=32") in new stack
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'Gosub'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [calldone@call-cust-03:3] Gosub("SIP/innovative-b7d00468", "updatedur|1") in new stack
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Expression result is '0'
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'GotoIf'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [updatedur@call-cust-03:1] GotoIf("SIP/innovative-b7d00468", "0?exit|1") in new stack
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Not taking any branch
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'Verbose'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [updatedur@call-cust-03:2] Verbose("SIP/innovative-b7d00468", "1|[7147832205-inn] Updating Duration in DNISLookUP for 7147832205 with 32 seconds") in new stack
[Jun 19 14:12:04] VERBOSE[11890] logger.c: [7147832205-inn] Updating Duration in DNISLookUP for 7147832205 with 32 seconds
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'MYSQL'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [updatedur@call-cust-03:3] MYSQL("SIP/innovative-b7d00468", "Connect connid localhost root passw0rd dax") in new stack
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'MYSQL'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [updatedur@call-cust-03:4] MYSQL("SIP/innovative-b7d00468", "Query resultid 1 UPDATE dnislookup SET duration=duration+32 WHERE dnis=7147832205") in new stack
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'MYSQL'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [updatedur@call-cust-03:5] MYSQL("SIP/innovative-b7d00468", "Clear ") in new stack
[Jun 19 14:12:04] WARNING[11890] app_addon_sql_mysql.c: Identifier 0, identifier_type 2 not found in identifier list
[Jun 19 14:12:04] WARNING[11890] app_addon_sql_mysql.c: Invalid result identifier 0 passed in aMYSQL_clear
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'MYSQL'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [updatedur@call-cust-03:6] MYSQL("SIP/innovative-b7d00468", "Disconnect 1") in new stack
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'Set'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [updatedur@call-cust-03:7] Set("SIP/innovative-b7d00468", "CALLLOGED=Y") in new stack
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'Return'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [updatedur@call-cust-03:8] Return("SIP/innovative-b7d00468", "") in new stack
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Function result is '05:12:04'
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'Verbose'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [calldone@call-cust-03:4] Verbose("SIP/innovative-b7d00468", "1|[7147832205-inn] Exit START:[14:11] END:[05:12:04] DUR:[32] ") in new stack
[Jun 19 14:12:04] VERBOSE[11890] logger.c: [7147832205-inn] Exit START:[14:11] END:[05:12:04] DUR:[32]
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Launching 'Hangup'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: -- Executing [calldone@call-cust-03:5] Hangup("SIP/innovative-b7d00468", "") in new stack
[Jun 19 14:12:04] DEBUG[11890] pbx.c: Spawn extension (call-cust-03,calldone,5) exited non-zero on 'SIP/innovative-b7d00468'
[Jun 19 14:12:04] VERBOSE[11890] logger.c: == Spawn extension (call-cust-03, calldone, 5) exited non-zero on 'SIP/innovative-b7d00468'
[Jun 19 14:12:04] DEBUG[11890] channel.c: Hanging up channel 'SIP/innovative-b7d00468'
[Jun 19 14:12:04] DEBUG[11890] chan_sip.c: Hangup call SIP/innovative-b7d00468, SIP callid 015d297d15a0bd397429c4a70ba8660e@64.2.142.30)
[Jun 19 14:12:04] DEBUG[11890] 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 19 14:12:04] DEBUG[11890] devicestate.c: Notification of state change to be queued on device/channel SIP/innovative-b7d00468
[Jun 19 14:12:04] DEBUG[11270] devicestate.c: No provider found, checking channel drivers for SIP - innovative-b7d00468
[Jun 19 14:12:04] DEBUG[11270] chan_sip.c: Checking device state for peer innovative-b7d00468
[Jun 19 14:12:04] DEBUG[11890] devicestate.c: Notification of state change to be queued on device/channel SIP/innovative
[Jun 19 14:12:04] DEBUG[11890] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
[Jun 19 14:12:04] DEBUG[11890] 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-19 14:11:32','\"Cell Phone CA\" <7142318220>','7142318220','7147832205','call-cust-03', 'SIP/innovative-b7d00468','Zap/97-1','Dial','Zap/g5/*7142318220*2205*|10|r',32,15,'ANSWERED',3,'7147832205')
[Jun 19 14:12:04] DEBUG[11270] devicestate.c: Changing state for SIP/innovative-b7d00468 - state 4 (Invalid)
[Jun 19 14:12:04] DEBUG[11270] devicestate.c: No provider found, checking channel drivers for SIP - innovative
[Jun 19 14:12:04] DEBUG[11272] app_queue.c: Device 'SIP/innovative-b7d00468' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jun 19 14:12:04] DEBUG[11270] chan_sip.c: Checking device state for peer innovative
[Jun 19 14:12:04] DEBUG[11270] devicestate.c: Changing state for SIP/innovative - state 1 (Not in use)
[Jun 19 14:12:04] DEBUG[11272] 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 19 14:12:04] DEBUG[11288] chan_zap.c: Monitor doohicky got event On hook on channel 97
[Jun 19 14:12:04] DEBUG[11288] chan_zap.c: disabled echo cancellation on channel 97
[Jun 19 14:12:05] VERBOSE[11291] logger.c: Really destroying SIP dialog '015d297d15a0bd397429c4a70ba8660e@64.2.142.30' Method: BYE
[Jun 19 14:12:12] DEBUG[11899] manager.c: Manager received command 'login'
[Jun 19 14:12:12] VERBOSE[11899] logger.c: == Parsing '/etc/asterisk/manager.conf': [Jun 19 14:12:12] DEBUG[11899] config.c: Parsing /etc/asterisk/manager.conf
[Jun 19 14:12:12] VERBOSE[11899] logger.c: Found
[Jun 19 14:12:12] VERBOSE[11899] logger.c: == Parsing '/etc/asterisk/manager_additional.conf': [Jun 19 14:12:12] DEBUG[11899] config.c: Parsing /etc/asterisk/manager_additional.conf
[Jun 19 14:12:12] VERBOSE[11899] logger.c: Found
[Jun 19 14:12:12] VERBOSE[11899] logger.c: == Parsing '/etc/asterisk/manager_custom.conf': [Jun 19 14:12:12] DEBUG[11899] config.c: Parsing /etc/asterisk/manager_custom.conf
[Jun 19 14:12:12] VERBOSE[11899] logger.c: Found
[Jun 19 14:12:12] DEBUG[11899] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
[Jun 19 14:12:12] DEBUG[11899] acl.c: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
[Jun 19 14:12:12] DEBUG[11899] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
[Jun 19 14:12:12] DEBUG[11899] acl.c: ##### Testing 127.0.0.1 with 127.0.0.0
[Jun 19 14:12:12] VERBOSE[11899] logger.c: == Manager 'admin' logged on from 127.0.0.1
[Jun 19 14:12:12] VERBOSE[11899] logger.c: == Manager 'admin' logged on from 127.0.0.1