[asterisk-users] Asterisk HangUp not breaking incoming call for caller

Tue Sep 11 12:06:22 CDT 2012

Hi,

Asterisk 1.8.13 on Debian Testing (Wheezy), MTNL Mumbai.
Digium, Inc. Wildcard AEX410 4-port analog card (PCI-Express)

When Asterisk executes HangUp() on an incoming call, the line remains
connected for the caller.

Zone = in, opermode = INDIA.  Line set to fxsks.  Any help on where to
start looking appreciated.

Sample log:
[Sep 11 22:06:18] DEBUG[4759]: chan_dahdi.c:11895 do_monitor: Monitor 
doohicky got event Ring Begin on channel 1
[Sep 11 22:06:18] DEBUG[4759]: sig_analog.c:3621 
analog_handle_init_event: channel (1) - signaling (5) - event 
(ANALOG_EVENT_RINGBEGIN)
[Sep 11 22:06:19] DEBUG[4759]: chan_dahdi.c:11895 do_monitor: Monitor 
doohicky got event Ring/Answered on channel 1
[Sep 11 22:06:19] DEBUG[4759]: sig_analog.c:3621 
analog_handle_init_event: channel (1) - signaling (5) - event 
(ANALOG_EVENT_RINGOFFHOOK)
[Sep 11 22:06:19] DEBUG[4759]: dsp.c:471 ast_tone_detect_init: Setup 
tone 1100 Hz, 500 ms, block_size=160, hits_required=21
[Sep 11 22:06:19] DEBUG[4759]: dsp.c:471 ast_tone_detect_init: Setup 
tone 2100 Hz, 2600 ms, block_size=160, hits_required=116
[Sep 11 22:06:19] DEBUG[4759]: dsp.c:1576 ast_dsp_set_busy_pattern: dsp 
busy pattern set to 0,0
[Sep 11 22:06:19] DEBUG[4737]: devicestate.c:340 _ast_device_state: No 
provider found, checking channel drivers for DAHDI - 1
[Sep 11 22:06:19] DEBUG[5414]: sig_analog.c:1769 __analog_ss_thread: 
__analog_ss_thread 1
    -- Starting simple switch on 'DAHDI/1-1'
[Sep 11 22:06:19] DEBUG[4737]: devicestate.c:458 do_state_change: 
Changing state for DAHDI/1 - state 2 (In use)
[Sep 11 22:06:19] DEBUG[4737]: devicestate.c:438 devstate_event: device 
'DAHDI/1' state '2'
[Sep 11 22:06:19] DEBUG[5414]: sig_analog.c:2392 __analog_ss_thread: 
Receiving DTMF cid on channel DAHDI/1-1
[Sep 11 22:06:19] DEBUG[4772]: app_queue.c:1487 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.
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:3509 analog_exception: 
analog_exception 1
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:3603 analog_exception: 
Exception on 16, channel 1
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:2660 __analog_handle_event: 
__analog_handle_event 1
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:2687 __analog_handle_event: 
Got event ANALOG_EVENT_RINGBEGIN(12) on channel 1 (index 0)
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:3509 analog_exception: 
analog_exception 1
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:3603 analog_exception: 
Exception on 16, channel 1
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:2660 __analog_handle_event: 
__analog_handle_event 1
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:2687 __analog_handle_event: 
Got event ANALOG_EVENT_RINGOFFHOOK(2) on channel 1 (index 0)
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:3043 __analog_handle_event: 
Ring detected
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:2441 __analog_ss_thread: CID 
got string ''
[Sep 11 22:06:21] DEBUG[5414]: callerid.c:207 callerid_get_dtmf: No cid 
detected
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:2443 __analog_ss_thread: CID 
is '', flags 8
[Sep 11 22:06:21] DEBUG[5414]: pbx.c:3239 ast_str_retrieve_variable: 
Result of 'EXTEN' is 's'
[Sep 11 22:06:21] DEBUG[4737]: devicestate.c:340 _ast_device_state: No 
provider found, checking channel drivers for DAHDI - 1
[Sep 11 22:06:21] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: 
Launching 'NoOp'
[Sep 11 22:06:21] DEBUG[4737]: devicestate.c:458 do_state_change: 
Changing state for DAHDI/1 - state 2 (In use)
[Sep 11 22:06:21] DEBUG[4737]: devicestate.c:438 devstate_event: device 
'DAHDI/1' state '2'
    -- Executing [s at incoming:1] NoOp("DAHDI/1-1", "Incoming s") in new 
stack
[Sep 11 22:06:21] DEBUG[5414]: pbx.c:4058 
pbx_substitute_variables_helper_full: Function result is ''
[Sep 11 22:06:21] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: 
Launching 'Verbose'
    -- Executing [s at incoming:2] Verbose("DAHDI/1-1", "CID ") in new 
stack
CID 
[Sep 11 22:06:21] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: 
Launching 'Set'
    -- Executing [s at incoming:3] Set("DAHDI/1-1", "SPYGROUP=queue-01") in 
new stack
[Sep 11 22:06:21] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: 
Launching 'Answer'
    -- Executing [s at incoming:4] Answer("DAHDI/1-1", "") in new stack
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:1499 analog_answer: 
analog_answer 1
[Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:1530 analog_answer: Took 
DAHDI/1-1 off hook
[Sep 11 22:06:21] DEBUG[5414]: chan_dahdi.c:4927 dahdi_enable_ec: 
Enabled echo cancellation on channel 1
[Sep 11 22:06:21] DEBUG[4737]: devicestate.c:340 _ast_device_state: No 
provider found, checking channel drivers for DAHDI - 1
[Sep 11 22:06:21] DEBUG[5414]: chan_dahdi.c:4946 dahdi_train_ec: No echo 
training requested
[Sep 11 22:06:21] DEBUG[5414]: chan_dahdi.c:9403 dahdi_indicate: 
Requested indication -1 on channel DAHDI/1-1
[Sep 11 22:06:21] DEBUG[4772]: app_queue.c:1487 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.
[Sep 11 22:06:21] DEBUG[4737]: devicestate.c:458 do_state_change: 
Changing state for DAHDI/1 - state 2 (In use)
[Sep 11 22:06:21] DEBUG[4737]: devicestate.c:438 devstate_event: device 
'DAHDI/1' state '2'
[Sep 11 22:06:21] DEBUG[4772]: app_queue.c:1487 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.
[Sep 11 22:06:21] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: 
Launching 'AGI'
    -- Executing [s at incoming:5] AGI("DAHDI/1-1", 
"/usr/local/lib/agi/office-hours.agi,custom/no-service") in new stack
    -- Launched AGI Script /usr/local/lib/agi/office-hours.agi
       > /usr/local/lib/agi/office-hours.agi,custom/no-service: FILE 
custom/no-service
 /usr/local/lib/agi/office-hours.agi,custom/no-service: Week day 2
 /usr/local/lib/agi/office-hours.agi,custom/no-service: OS: 36000, OE: 
79200, CUR: 79581
    -- AGI Script Executing Application: (Playback) Options: 
(custom/test)
[Sep 11 22:06:21] DEBUG[5414]: channel.c:5171 set_format: Set channel 
DAHDI/1-1 to write format slin
[Sep 11 22:06:21] DEBUG[5414]: channel.c:3506 ast_settimeout: Scheduling 
timer at (50 requested / 50 actual) timer ticks per second
    -- <DAHDI/1-1> Playing 'custom/test.slin' (language 'en')
[Sep 11 22:06:28] DEBUG[5414]: channel.c:3506 ast_settimeout: Scheduling 
timer at (52 requested / 52 actual) timer ticks per second
[Sep 11 22:06:28] DEBUG[5414]: channel.c:3506 ast_settimeout: Scheduling 
timer at (0 requested / 0 actual) timer ticks per second
[Sep 11 22:06:28] DEBUG[5414]: channel.c:3506 ast_settimeout: Scheduling 
timer at (0 requested / 0 actual) timer ticks per second
[Sep 11 22:06:28] DEBUG[5414]: channel.c:3506 ast_settimeout: Scheduling 
timer at (0 requested / 0 actual) timer ticks per second
[Sep 11 22:06:28] DEBUG[5414]: channel.c:5171 set_format: Set channel 
DAHDI/1-1 to write format ulaw
    -- <DAHDI/1-1>AGI Script /usr/local/lib/agi/office-hours.agi 
completed, returning 0
[Sep 11 22:06:28] DEBUG[5414]: pbx.c:3239 ast_str_retrieve_variable: 
Result of 'PASS' is '0'
[Sep 11 22:06:28] DEBUG[5414]: pbx.c:4126 
pbx_substitute_variables_helper_full: Expression result is '1'
[Sep 11 22:06:28] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: 
Launching 'GotoIf'
    -- Executing [s at incoming:6] GotoIf("DAHDI/1-1", "1 ?done") in new 
stack
    -- Goto (incoming,s,12)
[Sep 11 22:06:28] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: 
Launching 'NoOp'
    -- Executing [s at incoming:12] NoOp("DAHDI/1-1", "") in new stack
[Sep 11 22:06:28] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: 
Launching 'Hangup'
    -- Executing [s at incoming:13] Hangup("DAHDI/1-1", "") in new stack
[Sep 11 22:06:28] DEBUG[5414]: pbx.c:5047 __ast_pbx_run: Spawn extension 
(incoming,s,13) exited non-zero on 'DAHDI/1-1'
  == Spawn extension (incoming, s, 13) exited non-zero on 'DAHDI/1-1'
[Sep 11 22:06:28] DEBUG[5414]: channel.c:2683 ast_softhangup_nolock: 
Soft-Hanging up channel 'DAHDI/1-1'
[Sep 11 22:06:28] DEBUG[5414]: channel.c:2831 ast_hangup: Hanging up 
channel 'DAHDI/1-1'
[Sep 11 22:06:28] DEBUG[5414]: chan_dahdi.c:6149 dahdi_hangup: 
dahdi_hangup(DAHDI/1-1)
[Sep 11 22:06:28] DEBUG[5414]: sig_analog.c:1282 analog_hangup: 
analog_hangup 1
[Sep 11 22:06:28] DEBUG[5414]: sig_analog.c:1305 analog_hangup: Hangup: 
channel: 1 index = 0, normal = 1, callwait = 0, thirdcall = 0
[Sep 11 22:06:28] DEBUG[5414]: chan_dahdi.c:4962 dahdi_disable_ec: 
Disabled echo cancellation on channel 1
[Sep 11 22:06:28] DEBUG[5414]: chan_dahdi.c:6747 dahdi_setoption: Set 
option TONE VERIFY, mode: OFF(0) on DAHDI/1-1
[Sep 11 22:06:28] DEBUG[5414]: chan_dahdi.c:6757 dahdi_setoption: Set 
option TDD MODE, value: OFF(0) on DAHDI/1-1
[Sep 11 22:06:28] DEBUG[5414]: sig_analog.c:782 analog_update_conf: 
Updated conferencing on 1, with 0 conference users
    -- Hanging up on 'DAHDI/1-1'
    -- Hungup 'DAHDI/1-1'
[Sep 11 22:06:28] DEBUG[5414]: res_odbc.c:1050 odbc_release_obj2: 
odbc_release_obj2(0x7f537401ac78) called (obj->txf = (nil))
[Sep 11 22:06:28] DEBUG[5414]: cdr_radius.c:208 radius_log: Unable to 
create RADIUS record. CDR not recorded!
[Sep 11 22:06:28] DEBUG[5414]: res_config_sqlite.c:834 cdr_handler: SQL 
query: INSERT INTO ast_cdr 
(dst,dcontext,channel,lastapp,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) 
VALUES ('s','incoming','DAHDI/1-1','Hangup','2012-09-11 
22:06:19','2012-09-11 22:06:21','2012-09-11 
22:06:28','9','7','ANSWERED','DOCUMENTATION','1347381379.5')
[Sep 11 22:06:28] DEBUG[4737]: devicestate.c:340 _ast_device_state: No 
provider found, checking channel drivers for DAHDI - 1
[Sep 11 22:06:28] DEBUG[4737]: devicestate.c:458 do_state_change: 
Changing state for DAHDI/1 - state 0 (Unknown)
[Sep 11 22:06:28] DEBUG[4737]: devicestate.c:438 devstate_event: device 
'DAHDI/1' state '0'
[Sep 11 22:06:28] DEBUG[4772]: app_queue.c:1487 handle_statechange: 
Device 'DAHDI/1' changed to state '0' (Unknown) but we don't care 
because they're not a member of any queue.

Regards,

-- Raj
-- 
Raj Mathur                          || raju at kandalaya.org   || GPG:
http://otheronepercent.blogspot.com || http://kandalaya.org || CC68
It is the mind that moves           || http://schizoid.in   || D17F