2013-04-11 11:06:58.262202 [DEBUG] ftmod_wanpipe.c:1678 [s1c1][1:7] read wanpipe event 5
2013-04-11 11:06:58.262202 [DEBUG] ftmod_wanpipe.c:1462 [s1c1][1:7] Got wanpipe OFFHOOK
2013-04-11 11:06:58.262202 [DEBUG] ftmod_wanpipe.c:1685 [s1c1][1:7] Ignoring event for now
2013-04-11 11:06:58.402203 [DEBUG] ftmod_wanpipe.c:1642 [s1c1][1:7] Diff since last event = 151 ms, delivering OFFHOOK now
2013-04-11 11:06:58.402203 [DEBUG] ftmod_analog.c:1001 [s1c1][1:7] Received event [OFFHOOK] in state [DOWN]
2013-04-11 11:06:58.402203 [DEBUG] ftmod_analog.c:1094 [s1c1][1:7] Changed state from DOWN to DIALTONE
2013-04-11 11:06:58.402203 [DEBUG] ftmod_analog.c:439 [s1c1][1:7] ANALOG CHANNEL thread starting.
2013-04-11 11:06:58.402203 [DEBUG] ftdm_io.c:3386 [s1c1][1:7] Enabled software DTMF detector
2013-04-11 11:06:58.402203 [DEBUG] ftmod_analog.c:459 [s1c1][1:7] Initialized DTMF detection
2013-04-11 11:06:58.402203 [DEBUG] ftmod_analog.c:640 [s1c1][1:7] Completed state change from DOWN to DIALTONE in 0 ms
2013-04-11 11:06:58.402203 [DEBUG] ftmod_analog.c:646 [s1c1][1:7] Executing state handler on 1:1 for DIALTONE
2013-04-11 11:06:58.422206 [DEBUG] ftmod_wanpipe.c:1002 [s1c1][1:7] First packet read stats: Rx queue len: 0, Rx queue size: 10
2013-04-11 11:06:58.422206 [DEBUG] ftmod_wanpipe.c:938 [s1c1][1:7] First packet write stats: Tx queue len: 1, Tx queue size: 5, Tx idle: 20
2013-04-11 11:07:00.522222 [DEBUG] ftdm_io.c:3783 [s1c1][1:7] Queuing DTMF 7 (debug = 0)
2013-04-11 11:07:00.522222 [DEBUG] ftmod_analog.c:830 [s1c1][1:7] Changed state from DIALTONE to COLLECT
2013-04-11 11:07:00.522222 [DEBUG] mod_freetdm.c:2318 got FXS sig [COLLECTED_DIGIT]
2013-04-11 11:07:00.522222 [DEBUG] mod_freetdm.c:2488 got DTMF sig [7]
2013-04-11 11:07:00.542222 [DEBUG] ftmod_analog.c:640 [s1c1][1:7] Completed state change from DIALTONE to COLLECT in 20 ms
2013-04-11 11:07:00.542222 [DEBUG] ftmod_analog.c:646 [s1c1][1:7] Executing state handler on 1:1 for COLLECT
2013-04-11 11:07:02.542242 [DEBUG] ftmod_analog.c:851 [s1c1][1:7] Number obtained [7]
2013-04-11 11:07:02.542242 [DEBUG] ftmod_analog.c:852 [s1c1][1:7] Changed state from COLLECT to RING
2013-04-11 11:07:02.562239 [DEBUG] ftmod_analog.c:640 [s1c1][1:7] Completed state change from COLLECT to RING in 20 ms
2013-04-11 11:07:02.562239 [DEBUG] ftmod_analog.c:646 [s1c1][1:7] Executing state handler on 1:1 for RING
2013-04-11 11:07:02.562239 [DEBUG] mod_freetdm.c:2318 got FXS sig [START]
2013-04-11 11:07:02.562239 [DEBUG] ftdm_io.c:3386 [s1c1][1:7] Enabled software DTMF detector
2013-04-11 11:07:02.562239 [DEBUG] mod_freetdm.c:403 Set codec PCMU 20ms
2013-04-11 11:07:02.562239 [DEBUG] mod_freetdm.c:1886 Connect inbound channel FreeTDM/1:1/7
2013-04-11 11:07:02.562239 [NOTICE] switch_channel.c:968 New Channel FreeTDM/1:1/7 [ba9a7e14-9151-4b7d-90a8-12df300c4efb]
2013-04-11 11:07:02.562239 [DEBUG] mod_freetdm.c:2089 (FreeTDM/1:1/7) State Change CS_NEW -> CS_INIT
2013-04-11 11:07:02.562239 [DEBUG] switch_core_session.c:1283 Send signal FreeTDM/1:1/7 [BREAK]
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:415 (FreeTDM/1:1/7) Running State Change CS_INIT
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:454 (FreeTDM/1:1/7) State INIT
2013-04-11 11:07:02.562239 [DEBUG] mod_freetdm.c:430 (FreeTDM/1:1/7) State Change CS_INIT -> CS_ROUTING
2013-04-11 11:07:02.562239 [DEBUG] switch_core_session.c:1283 Send signal FreeTDM/1:1/7 [BREAK]
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:454 (FreeTDM/1:1/7) State INIT going to sleep
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:415 (FreeTDM/1:1/7) Running State Change CS_ROUTING
2013-04-11 11:07:02.562239 [DEBUG] switch_channel.c:2003 (FreeTDM/1:1/7) Callstate Change DOWN -> RINGING
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:470 (FreeTDM/1:1/7) State ROUTING
2013-04-11 11:07:02.562239 [DEBUG] mod_freetdm.c:453 FreeTDM/1:1/7 CHANNEL ROUTING
2013-04-11 11:07:02.562239 [DEBUG] mod_freetdm.c:456 [s1c1][1:7] Indicating PROCEED in state RING
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:117 FreeTDM/1:1/7 Standard ROUTING
2013-04-11 11:07:02.562239 [INFO] mod_dialplan_xml.c:557 Processing freetdm <0000000000>->7 in context default
Dialplan: FreeTDM/1:1/7 parsing [default->Call out business hours(Staff)] continue=true
Dialplan: FreeTDM/1:1/7 Regex (FAIL) [Call out business hours(Staff)] ani() =~ /^(1014|1015)/ break=on-true
Dialplan: FreeTDM/1:1/7 Date/Time Match (PASS) [Call out business hours(Staff)] break=on-false
Dialplan: FreeTDM/1:1/7 Regex (FAIL) [Call out business hours(Staff)] destination_number(7) =~ /^7(.+)$/ break=on-false
Dialplan: FreeTDM/1:1/7 parsing [default->bridge-FXS-to-FXO] continue=true
Dialplan: FreeTDM/1:1/7 Regex (FAIL) [bridge-FXS-to-FXO] destination_number(7) =~ /^7(\d{7}|1\d{10})$/ break=on-false
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:167 (FreeTDM/1:1/7) State Change CS_ROUTING -> CS_EXECUTE
2013-04-11 11:07:02.562239 [DEBUG] switch_core_session.c:1283 Send signal FreeTDM/1:1/7 [BREAK]
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:470 (FreeTDM/1:1/7) State ROUTING going to sleep
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:415 (FreeTDM/1:1/7) Running State Change CS_EXECUTE
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:477 (FreeTDM/1:1/7) State EXECUTE
2013-04-11 11:07:02.562239 [DEBUG] mod_freetdm.c:473 FreeTDM/1:1/7 CHANNEL EXECUTE
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:209 FreeTDM/1:1/7 Standard EXECUTE
EXECUTE FreeTDM/1:1/7 set(open=true)
2013-04-11 11:07:02.562239 [DEBUG] mod_dptools.c:1344 FreeTDM/1:1/7 SET [open]=[true]
EXECUTE FreeTDM/1:1/7 hash(insert/192.168.1.11-spymap/0000000000/ba9a7e14-9151-4b7d-90a8-12df300c4efb)
EXECUTE FreeTDM/1:1/7 hash(insert/192.168.1.11-last_dial/0000000000/7)
EXECUTE FreeTDM/1:1/7 hash(insert/192.168.1.11-last_dial/global/ba9a7e14-9151-4b7d-90a8-12df300c4efb)
EXECUTE FreeTDM/1:1/7 set(RFC2822_DATE=Thu, 11 Apr 2013 11:07:02 -0600)
2013-04-11 11:07:02.562239 [DEBUG] mod_dptools.c:1344 FreeTDM/1:1/7 SET [RFC2822_DATE]=[Thu, 11 Apr 2013 11:07:02 -0600]
2013-04-11 11:07:02.562239 [NOTICE] switch_core_state_machine.c:262 FreeTDM/1:1/7 has executed the last dialplan instruction, hanging up.
2013-04-11 11:07:02.562239 [DEBUG] switch_channel.c:2994 (FreeTDM/1:1/7) Callstate Change RINGING -> HANGUP
2013-04-11 11:07:02.562239 [NOTICE] switch_core_state_machine.c:264 Hangup FreeTDM/1:1/7 [CS_EXECUTE] [NORMAL_CLEARING]
2013-04-11 11:07:02.562239 [DEBUG] switch_channel.c:3017 Send signal FreeTDM/1:1/7 [KILL]
2013-04-11 11:07:02.562239 [DEBUG] switch_core_session.c:1283 Send signal FreeTDM/1:1/7 [BREAK]
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:477 (FreeTDM/1:1/7) State EXECUTE going to sleep
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:415 (FreeTDM/1:1/7) Running State Change CS_HANGUP
2013-04-11 11:07:02.562239 [DEBUG] switch_core_state_machine.c:667 (FreeTDM/1:1/7) State HANGUP
2013-04-11 11:07:02.562239 [DEBUG] mod_freetdm.c:540 [1:1] FreeTDM/1:1/7 CHANNEL HANGUP ENTER
2013-04-11 11:07:02.562239 [DEBUG] mod_freetdm.c:596 [s1c1][1:7] Changed state from RING to HANGUP
2013-04-11 11:07:02.582241 [DEBUG] ftdm_io.c:489 [s1c1][1:7] Enabling ec back on call end in channel state HANGUP
2013-04-11 11:07:02.582241 [DEBUG] ftmod_analog.c:640 [s1c1][1:7] Completed state change from RING to HANGUP in 19 ms
2013-04-11 11:07:02.582241 [DEBUG] ftmod_analog.c:646 [s1c1][1:7] Executing state handler on 1:1 for HANGUP
2013-04-11 11:07:02.582241 [DEBUG] mod_freetdm.c:636 [1:1] FreeTDM/1:1/7 CHANNEL HANGUP EXIT
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:48 FreeTDM/1:1/7 Standard HANGUP, cause: NORMAL_CLEARING
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:667 (FreeTDM/1:1/7) State HANGUP going to sleep
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:446 (FreeTDM/1:1/7) State Change CS_HANGUP -> CS_REPORTING
2013-04-11 11:07:02.582241 [DEBUG] switch_core_session.c:1283 Send signal FreeTDM/1:1/7 [BREAK]
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:415 (FreeTDM/1:1/7) Running State Change CS_REPORTING
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:749 (FreeTDM/1:1/7) State REPORTING
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:92 FreeTDM/1:1/7 Standard REPORTING, cause: NORMAL_CLEARING
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:749 (FreeTDM/1:1/7) State REPORTING going to sleep
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:440 (FreeTDM/1:1/7) State Change CS_REPORTING -> CS_DESTROY
2013-04-11 11:07:02.582241 [DEBUG] switch_core_session.c:1283 Send signal FreeTDM/1:1/7 [BREAK]
2013-04-11 11:07:02.582241 [DEBUG] switch_core_session.c:1488 Session 213 (FreeTDM/1:1/7) Locked, Waiting on external entities
2013-04-11 11:07:02.582241 [NOTICE] switch_core_session.c:1506 Session 213 (FreeTDM/1:1/7) Ended
2013-04-11 11:07:02.582241 [NOTICE] switch_core_session.c:1510 Close Channel FreeTDM/1:1/7 [CS_DESTROY]
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:556 (FreeTDM/1:1/7) Callstate Change HANGUP -> DOWN
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:559 (FreeTDM/1:1/7) Running State Change CS_DESTROY
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:569 (FreeTDM/1:1/7) State DESTROY
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:99 FreeTDM/1:1/7 Standard DESTROY
2013-04-11 11:07:02.582241 [DEBUG] switch_core_state_machine.c:569 (FreeTDM/1:1/7) State DESTROY going to sleep
2013-04-11 11:07:02.762244 [DEBUG] ftdm_io.c:3783 [s1c1][1:7] Queuing DTMF 2 (debug = 0)
2013-04-11 11:07:03.082244 [DEBUG] ftmod_analog.c:561 [s1c1][1:7] Changed state from HANGUP to BUSY
2013-04-11 11:07:03.102244 [DEBUG] ftmod_analog.c:640 [s1c1][1:7] Completed state change from HANGUP to BUSY in 20 ms
2013-04-11 11:07:03.102244 [DEBUG] ftmod_analog.c:646 [s1c1][1:7] Executing state handler on 1:1 for BUSY
2013-04-11 11:07:05.242263 [DEBUG] ftmod_wanpipe.c:1678 [s1c1][1:7] read wanpipe event 5
2013-04-11 11:07:05.242263 [DEBUG] ftmod_wanpipe.c:1462 [s1c1][1:7] Got wanpipe ONHOOK
2013-04-11 11:07:05.242263 [DEBUG] ftmod_wanpipe.c:1685 [s1c1][1:7] Ignoring event for now
2013-04-11 11:07:06.002270 [DEBUG] ftmod_wanpipe.c:1661 [s1c1][1:7] Diff since last event = 755 ms, delivering ONHOOK now
2013-04-11 11:07:06.002270 [DEBUG] ftmod_analog.c:1001 [s1c1][1:7] Received event [ONHOOK] in state [BUSY]
2013-04-11 11:07:06.002270 [DEBUG] ftmod_analog.c:1054 [s1c1][1:7] Changed state from BUSY to DOWN
2013-04-11 11:07:06.002270 [DEBUG] ftmod_analog.c:640 [s1c1][1:7] Completed state change from BUSY to DOWN in 10 ms
2013-04-11 11:07:06.002270 [DEBUG] ftmod_analog.c:646 [s1c1][1:7] Executing state handler on 1:1 for DOWN
2013-04-11 11:07:06.002270 [DEBUG] ftdm_io.c:6145 [s1c1][1:7] Ignoring SIGEVENT_STOP since user already requested hangup
2013-04-11 11:07:06.002270 [DEBUG] ftdm_io.c:3185 [s1c1][1:7] DTMF debug is already disabled
2013-04-11 11:07:06.002270 [DEBUG] ftdm_io.c:3217 [s1c1][1:7] No need to disable input dump
2013-04-11 11:07:06.002270 [DEBUG] ftdm_io.c:3248 [s1c1][1:7] No need to disable output dump
2013-04-11 11:07:06.002270 [DEBUG] ftdm_io.c:6780 Cleared call with id 66
2013-04-11 11:07:06.002270 [DEBUG] ftdm_io.c:2990 [s1c1][1:7] channel done
2013-04-11 11:07:06.002270 [DEBUG] ftmod_analog.c:974 [s1c1][1:7] ANALOG CHANNEL 1:1 thread ended.