*CLI> [Jun  2 12:43:03] DEBUG[30909]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel DAHDI/1-1
[Jun  2 12:43:03] DEBUG[30905]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1-1
[Jun  2 12:43:03] DEBUG[30905]: devicestate.c:441 do_state_change: Changing state for DAHDI/1-1 - state 0 (Unknown)
[Jun  2 12:43:03]     -- Accepting call from '6474483075' to '1008' on channel 0/1, span 1
[Jun  2 12:43:03] DEBUG[30909]: chan_dahdi.c:2011 dahdi_enable_ec: Enabled echo cancellation on channel 1
[Jun  2 12:43:03] DEBUG[30914]: pbx.c:3101 pbx_extension_helper: Launching 'BackGround'
[Jun  2 12:43:03]     -- Executing [1008@from-pstn:1] BackGround("DAHDI/1-1", "silence/1&custom/ivr_welcome") in new stack
[Jun  2 12:43:03] DEBUG[30911]: app_queue.c:766 handle_statechange: Device 'DAHDI/1-1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[Jun  2 12:43:03] DEBUG[30914]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel DAHDI/1
[Jun  2 12:43:03] DEBUG[30905]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1
[Jun  2 12:43:03] DEBUG[30914]: chan_dahdi.c:6029 dahdi_indicate: Requested indication -1 on channel DAHDI/1-1
[Jun  2 12:43:03] DEBUG[30905]: channel.c:1188 channel_find_locked: Avoiding initial deadlock for channel '0x91f4140'
[Jun  2 12:43:03] DEBUG[30905]: channel.c:1188 channel_find_locked: Avoiding initial deadlock for channel '0x91f4140'
[Jun  2 12:43:03] DEBUG[30905]: devicestate.c:441 do_state_change: Changing state for DAHDI/1 - state 2 (In use)
[Jun  2 12:43:03] DEBUG[30911]: app_queue.c:766 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:43:03] DEBUG[30914]: channel.c:2334 ast_settimeout: Scheduling timer at 160 sample intervals
[Jun  2 12:43:03]     -- <DAHDI/1-1> Playing 'silence/1.ulaw' (language 'en')
[Jun  2 12:43:04] DEBUG[30914]: channel.c:2334 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun  2 12:43:04] DEBUG[30914]: channel.c:2334 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun  2 12:43:04] DEBUG[30914]: channel.c:3505 set_format: Set channel DAHDI/1-1 to write format slin
[Jun  2 12:43:04] DEBUG[30914]: channel.c:2334 ast_settimeout: Scheduling timer at 160 sample intervals
[Jun  2 12:43:04]     -- <DAHDI/1-1> Playing 'custom/ivr_welcome.slin' (language 'en')
[Jun  2 12:43:09] DEBUG[30914]: chan_dahdi.c:5606 __dahdi_exception: Exception on 10, channel 1
[Jun  2 12:43:09] DEBUG[30914]: chan_dahdi.c:4705 dahdi_handle_event: Got event Event 131125(131125) on channel 1 (index 0)
[Jun  2 12:43:09] DEBUG[30914]: chan_dahdi.c:4725 dahdi_handle_event: DTMF Down '5'
[Jun  2 12:43:09] DTMF[30914]: channel.c:2806 __ast_read: DTMF begin '5' received on DAHDI/1-1
[Jun  2 12:43:09] DTMF[30914]: channel.c:2810 __ast_read: DTMF begin ignored '5' on DAHDI/1-1
[Jun  2 12:43:09] DEBUG[30914]: chan_dahdi.c:5606 __dahdi_exception: Exception on 10, channel 1
[Jun  2 12:43:09] DEBUG[30914]: chan_dahdi.c:4705 dahdi_handle_event: Got event Event 262197(262197) on channel 1 (index 0)
[Jun  2 12:43:09] DEBUG[30914]: chan_dahdi.c:4709 dahdi_handle_event: Detected digit '5'
[Jun  2 12:43:09] DEBUG[30914]: chan_dahdi.c:4587 dahdi_handle_dtmfup: DTMF digit: 5 on DAHDI/1-1
[Jun  2 12:43:09] DTMF[30914]: channel.c:2734 __ast_read: DTMF end '5' received on DAHDI/1-1, duration 0 ms
[Jun  2 12:43:09] DTMF[30914]: channel.c:2779 __ast_read: DTMF end accepted without begin '5' on DAHDI/1-1
[Jun  2 12:43:09] DTMF[30914]: channel.c:2790 __ast_read: DTMF end passthrough '5' on DAHDI/1-1
[Jun  2 12:43:09] DEBUG[30914]: channel.c:2334 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun  2 12:43:09] DEBUG[30914]: channel.c:3505 set_format: Set channel DAHDI/1-1 to write format ulaw
[Jun  2 12:43:09] DEBUG[30914]: pbx.c:3735 __ast_pbx_run: Oooh, got something to jump out with ('5')!
[Jun  2 12:43:15]   == CDR updated on DAHDI/1-1
[Jun  2 12:43:15] DEBUG[30914]: pbx.c:3101 pbx_extension_helper: Launching 'Playback'
[Jun  2 12:43:15]     -- Executing [5@from-pstn:1] Playback("DAHDI/1-1", "tt-weasels") in new stack
[Jun  2 12:43:15] DEBUG[30914]: channel.c:2334 ast_settimeout: Scheduling timer at 160 sample intervals
[Jun  2 12:43:15]     -- <DAHDI/1-1> Playing 'tt-weasels.ulaw' (language 'en')
[Jun  2 12:43:17] DEBUG[30914]: channel.c:2334 ast_settimeout: Scheduling timer at 79 sample intervals
[Jun  2 12:43:17] DEBUG[30914]: channel.c:2334 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun  2 12:43:17] DEBUG[30914]: channel.c:2334 ast_settimeout: Scheduling timer at 0 sample intervals
[Jun  2 12:43:17] DEBUG[30914]: pbx.c:3101 pbx_extension_helper: Launching 'Hangup'
[Jun  2 12:43:17]     -- Executing [5@from-pstn:2] Hangup("DAHDI/1-1", "") in new stack
[Jun  2 12:43:17] DEBUG[30914]: pbx.c:3740 __ast_pbx_run: Spawn extension (from-pstn,5,2) exited non-zero on 'DAHDI/1-1'
[Jun  2 12:43:17]   == Spawn extension (from-pstn, 5, 2) exited non-zero on 'DAHDI/1-1'
[Jun  2 12:43:17] DEBUG[30914]: channel.c:1584 ast_softhangup_nolock: Soft-Hanging up channel 'DAHDI/1-1'
[Jun  2 12:43:17] DEBUG[30914]: pbx.c:2935 pbx_substitute_variables_helper_full: Function result is '"LEIF MADSEN" <6474483075>'
[Jun  2 12:43:17] DEBUG[30914]: pbx.c:3101 pbx_extension_helper: Launching 'Verbose'
[Jun  2 12:43:17]     -- Executing [h@from-pstn:1] Verbose("DAHDI/1-1", "1,"LEIF MADSEN" <6474483075> hungup from from-pstn.") in new stack
[Jun  2 12:43:17]  "LEIF MADSEN" <6474483075> hungup from from-pstn.
[Jun  2 12:43:17] DEBUG[30914]: pbx.c:3101 pbx_extension_helper: Launching 'Hangup'
[Jun  2 12:43:17]     -- Executing [h@from-pstn:2] Hangup("DAHDI/1-1", "") in new stack
[Jun  2 12:43:17] DEBUG[30914]: pbx.c:3881 __ast_pbx_run: Spawn extension (from-pstn,h,2) exited non-zero on 'DAHDI/1-1'
[Jun  2 12:43:17]   == Spawn extension (from-pstn, h, 2) exited non-zero on 'DAHDI/1-1'
[Jun  2 12:43:17] DEBUG[30914]: channel.c:1677 ast_hangup: Hanging up channel 'DAHDI/1-1'
[Jun  2 12:43:17] DEBUG[30914]: chan_dahdi.c:3366 dahdi_hangup: dahdi_hangup(DAHDI/1-1)
[Jun  2 12:43:17] DEBUG[30914]: chan_dahdi.c:3956 dahdi_setoption: Set option AUDIO MODE, value: ON(1) on DAHDI/1-1
[Jun  2 12:43:17] DEBUG[30914]: chan_dahdi.c:3399 dahdi_hangup: Hangup: channel: 1 index = 0, normal = 10, callwait = -1, thirdcall = -1
[Jun  2 12:43:17] DEBUG[30914]: chan_dahdi.c:3578 dahdi_hangup: Not yet hungup...  Calling hangup once with icause, and clearing call
[Jun  2 12:43:17] DEBUG[30914]: chan_dahdi.c:2046 dahdi_disable_ec: Disabled echo cancellation on channel 1
[Jun  2 12:43:17] DEBUG[30914]: chan_dahdi.c:3872 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/1-1
[Jun  2 12:43:17] DEBUG[30914]: chan_dahdi.c:1981 update_conf: Updated conferencing on 1, with 0 conference users
[Jun  2 12:43:17] DEBUG[30914]: chan_dahdi.c:3952 dahdi_setoption: Set option AUDIO MODE, value: OFF(0) on DAHDI/1-1
[Jun  2 12:43:17]     -- Hungup 'DAHDI/1-1'
[Jun  2 12:43:17] DEBUG[30914]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel DAHDI/1
[Jun  2 12:43:17] DEBUG[30905]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1
[Jun  2 12:43:17] DEBUG[30905]: devicestate.c:441 do_state_change: Changing state for DAHDI/1 - state 0 (Unknown)
[Jun  2 12:43:17] DEBUG[30911]: app_queue.c:766 handle_statechange: Device 'DAHDI/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
stop now
[Jun  2 12:43:22] Beginning asterisk shutdown....
[Jun  2 12:43:22] Executing last minute cleanups
[Jun  2 12:43:22]   == Destroying musiconhold processes
[Jun  2 12:43:22] DEBUG[30899]: res_musiconhold.c:1369 moh_class_destructor: Destroying MOH class 'default'
[Jun  2 12:43:22] Asterisk cleanly ending (0).
[Jun  2 12:43:22] DEBUG[30899]: asterisk.c:1390 quit_handler: Asterisk ending (0).