*CLI> [Jun  2 12:45:13] DEBUG[31629]: devicestate.c:443 devstate_event: device 'DAHDI/1-1' state '2'
[Jun  2 12:45:13] DEBUG[31631]: app_queue.c:1060 handle_statechange: Device 'DAHDI/1-1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun  2 12:45:13] DEBUG[31635]: pbx.c:3672 pbx_extension_helper: Launching 'BackGround'
[Jun  2 12:45:13]     -- Executing [1008@from-pstn:1] BackGround("DAHDI/1-1", "silence/1&custom/ivr_welcome") in new stack
[Jun  2 12:45:13] DEBUG[31623]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1
[Jun  2 12:45:13] DEBUG[31635]: chan_dahdi.c:7116 dahdi_indicate: Requested indication -1 on channel DAHDI/1-1
[Jun  2 12:45:13] DEBUG[31623]: channel.c:1210 channel_find_locked: Avoiding initial deadlock for channel '0xa1bdf40'
[Jun  2 12:45:13] DEBUG[31623]: channel.c:1210 channel_find_locked: Avoiding initial deadlock for channel '0xa1bdf40'
[Jun  2 12:45:13] DEBUG[31623]: devicestate.c:463 do_state_change: Changing state for DAHDI/1 - state 2 (In use)
[Jun  2 12:45:13] DEBUG[31623]: devicestate.c:443 devstate_event: device 'DAHDI/1' state '2'
[Jun  2 12:45:13] DEBUG[31631]: app_queue.c:1060 handle_statechange: Device 'DAHDI/1' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun  2 12:45:13] DEBUG[31635]: channel.c:2359 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jun  2 12:45:13]     -- <DAHDI/1-1> Playing 'silence/1.ulaw' (language 'en')
[Jun  2 12:45:13]     -- Accepting call from '6474483075' to '1008' on channel 0/1, span 1
[Jun  2 12:45:13] DEBUG[31629]: chan_dahdi.c:2684 dahdi_enable_ec: Enabled echo cancellation on channel 1
[Jun  2 12:45:14] DEBUG[31635]: channel.c:2359 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jun  2 12:45:14] DEBUG[31635]: channel.c:2359 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jun  2 12:45:14] DEBUG[31635]: channel.c:3527 set_format: Set channel DAHDI/1-1 to write format slin
[Jun  2 12:45:14] DEBUG[31635]: channel.c:2359 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jun  2 12:45:14]     -- <DAHDI/1-1> Playing 'custom/ivr_welcome.slin' (language 'en')
[Jun  2 12:45:17] DEBUG[31635]: chan_dahdi.c:6638 __dahdi_exception: Exception on 11, channel 1
[Jun  2 12:45:17] DEBUG[31635]: chan_dahdi.c:5710 dahdi_handle_event: Got event Event 131125(131125) on channel 1 (index 0)
[Jun  2 12:45:17] DEBUG[31635]: chan_dahdi.c:5730 dahdi_handle_event: DTMF Down '5'
[Jun  2 12:45:17] DTMF[31635]: channel.c:2825 __ast_read: DTMF begin '5' received on DAHDI/1-1
[Jun  2 12:45:17] DTMF[31635]: channel.c:2829 __ast_read: DTMF begin ignored '5' on DAHDI/1-1
[Jun  2 12:45:18] DEBUG[31635]: chan_dahdi.c:6638 __dahdi_exception: Exception on 11, channel 1
[Jun  2 12:45:18] DEBUG[31635]: chan_dahdi.c:5710 dahdi_handle_event: Got event Event 262197(262197) on channel 1 (index 0)
[Jun  2 12:45:18] DEBUG[31635]: chan_dahdi.c:5714 dahdi_handle_event: Detected digit '5'
[Jun  2 12:45:18] DEBUG[31635]: chan_dahdi.c:5591 dahdi_handle_dtmfup: DTMF digit: 5 on DAHDI/1-1
[Jun  2 12:45:18] DTMF[31635]: channel.c:2753 __ast_read: DTMF end '5' received on DAHDI/1-1, duration 0 ms
[Jun  2 12:45:18] DTMF[31635]: channel.c:2798 __ast_read: DTMF end accepted without begin '5' on DAHDI/1-1
[Jun  2 12:45:18] DTMF[31635]: channel.c:2809 __ast_read: DTMF end passthrough '5' on DAHDI/1-1
[Jun  2 12:45:18] DEBUG[31635]: channel.c:2359 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jun  2 12:45:18] DEBUG[31635]: channel.c:3527 set_format: Set channel DAHDI/1-1 to write format ulaw
[Jun  2 12:45:18] DEBUG[31635]: pbx.c:4259 __ast_pbx_run: Oooh, got something to jump out with ('5')!
[Jun  2 12:45:23]   == CDR updated on DAHDI/1-1
[Jun  2 12:45:23] DEBUG[31635]: pbx.c:3672 pbx_extension_helper: Launching 'Playback'
[Jun  2 12:45:23]     -- Executing [5@from-pstn:1] Playback("DAHDI/1-1", "tt-weasels") in new stack
[Jun  2 12:45:23] DEBUG[31635]: channel.c:2359 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jun  2 12:45:23]     -- <DAHDI/1-1> Playing 'tt-weasels.ulaw' (language 'en')
[Jun  2 12:45:25] DEBUG[31635]: channel.c:2359 ast_settimeout: Scheduling timer at (101 requested / 101 actual) timer ticks per second
[Jun  2 12:45:25] DEBUG[31635]: channel.c:2359 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jun  2 12:45:25] DEBUG[31635]: channel.c:2359 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jun  2 12:45:25] DEBUG[31635]: pbx.c:3672 pbx_extension_helper: Launching 'Hangup'
[Jun  2 12:45:25]     -- Executing [5@from-pstn:2] Hangup("DAHDI/1-1", "") in new stack
[Jun  2 12:45:25] DEBUG[31635]: pbx.c:4276 __ast_pbx_run: Spawn extension (from-pstn,5,2) exited non-zero on 'DAHDI/1-1'
[Jun  2 12:45:25]   == Spawn extension (from-pstn, 5, 2) exited non-zero on 'DAHDI/1-1'
[Jun  2 12:45:25] DEBUG[31635]: channel.c:1600 ast_softhangup_nolock: Soft-Hanging up channel 'DAHDI/1-1'
[Jun  2 12:45:25] DEBUG[31635]: pbx.c:3502 pbx_substitute_variables_helper_full: Function result is '"LEIF MADSEN" <6474483075>'
[Jun  2 12:45:25] DEBUG[31635]: pbx.c:3672 pbx_extension_helper: Launching 'Verbose'
[Jun  2 12:45:25]     -- Executing [h@from-pstn:1] Verbose("DAHDI/1-1", "1,"LEIF MADSEN" <6474483075> hungup from from-pstn.") in new stack
[Jun  2 12:45:25]  "LEIF MADSEN" <6474483075> hungup from from-pstn.
[Jun  2 12:45:25] DEBUG[31635]: pbx.c:3672 pbx_extension_helper: Launching 'Hangup'
[Jun  2 12:45:25]     -- Executing [h@from-pstn:2] Hangup("DAHDI/1-1", "") in new stack
[Jun  2 12:45:25] DEBUG[31635]: pbx.c:4419 __ast_pbx_run: Spawn extension (from-pstn,h,2) exited non-zero on 'DAHDI/1-1'
[Jun  2 12:45:25]   == Spawn extension (from-pstn, h, 2) exited non-zero on 'DAHDI/1-1'
[Jun  2 12:45:25] DEBUG[31635]: channel.c:1695 ast_hangup: Hanging up channel 'DAHDI/1-1'
[Jun  2 12:45:25] DEBUG[31635]: chan_dahdi.c:4312 dahdi_hangup: dahdi_hangup(DAHDI/1-1)
[Jun  2 12:45:25] DEBUG[31635]: chan_dahdi.c:4959 dahdi_setoption: Set option AUDIO MODE, value: ON(1) on DAHDI/1-1
[Jun  2 12:45:25] DEBUG[31635]: chan_dahdi.c:4346 dahdi_hangup: Hangup: channel: 1 index = 0, normal = 11, callwait = -1, thirdcall = -1
[Jun  2 12:45:25] DEBUG[31635]: chan_dahdi.c:4557 dahdi_hangup: Not yet hungup...  Calling hangup once with icause, and clearing call
[Jun  2 12:45:25] DEBUG[31635]: chan_dahdi.c:2719 dahdi_disable_ec: Disabled echo cancellation on channel 1
[Jun  2 12:45:25] DEBUG[31635]: chan_dahdi.c:4875 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/1-1
[Jun  2 12:45:25] DEBUG[31635]: chan_dahdi.c:2654 update_conf: Updated conferencing on 1, with 0 conference users
[Jun  2 12:45:25] DEBUG[31635]: chan_dahdi.c:4955 dahdi_setoption: Set option AUDIO MODE, value: OFF(0) on DAHDI/1-1
[Jun  2 12:45:25]     -- Hungup 'DAHDI/1-1'
[Jun  2 12:45:25] DEBUG[31623]: devicestate.c:342 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1
[Jun  2 12:45:25] DEBUG[31623]: devicestate.c:463 do_state_change: Changing state for DAHDI/1 - state 0 (Unknown)
[Jun  2 12:45:25] DEBUG[31623]: devicestate.c:443 devstate_event: device 'DAHDI/1' state '0'
[Jun  2 12:45:25] DEBUG[31631]: app_queue.c:1060 handle_statechange: Device 'DAHDI/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
*CLI> core stop now
[Jun  2 12:45:31] Beginning asterisk shutdown....
[Jun  2 12:45:31] Executing last minute cleanups
[Jun  2 12:45:31]   == Destroying musiconhold processes
[Jun  2 12:45:31] DEBUG[31616]: res_musiconhold.c:1364 moh_class_destructor: Destroying MOH class 'default'
[Jun  2 12:45:31] Asterisk cleanly ending (0).
[Jun  2 12:45:31] DEBUG[31616]: asterisk.c:1617 quit_handler: Asterisk ending (0).