<p>This has been happening since the asterisk 1.2 days, makes me believe it has something to do with Analog FXO ckts provided.</p>
<p>Mitul Limbani</p>
<div class="gmail_quote">On Sep 12, 2012 10:18 AM, "Vladimir Mikhelson" <<a href="mailto:vlad@mikhelson.com">vlad@mikhelson.com</a>> wrote:<br type="attribution"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Raj,<br>
<br>
I am just confirming it happens here as well.<br>
<br>
CentOS 5.7. Asterisk 1.8.15.1. DAHDI 2.6.1.<br>
<br>
Digium, Inc. Wildcard TDM410 4-port analog card (rev 11)<br>
<br>
Loadzone = us<br>
<br>
The problem started manifesting itself after I switched to 1.8.x from<br>
1.6.2.x<br>
<br>
Typical scenario: a caller apparently hangs up, dial plan goes into<br>
voice mail and records a 50 sec message with the CO tones. Then<br>
something happens and the line finally gets hung up.<br>
<br>
Regards,<br>
Vladimir<br>
<br>
<br>
<br>
<br>
On 9/11/2012 12:08 PM, Raj Mathur (राज माथुर) wrote:<br>
> Hi,<br>
><br>
> Asterisk 1.8.13 on Debian Testing (Wheezy), MTNL Mumbai.<br>
> Digium, Inc. Wildcard AEX410 4-port analog card (PCI-Express)<br>
><br>
> When Asterisk executes HangUp() on an incoming call, the line remains<br>
> connected for the caller.<br>
><br>
> Zone = in, opermode = INDIA. Line set to fxsks. Any help on where to<br>
> start looking appreciated.<br>
><br>
> Sample log:<br>
> [Sep 11 22:06:18] DEBUG[4759]: chan_dahdi.c:11895 do_monitor: Monitor doohicky got event Ring Begin on channel 1<br>
> [Sep 11 22:06:18] DEBUG[4759]: sig_analog.c:3621 analog_handle_init_event: channel (1) - signaling (5) - event (ANALOG_EVENT_RINGBEGIN)<br>
> [Sep 11 22:06:19] DEBUG[4759]: chan_dahdi.c:11895 do_monitor: Monitor doohicky got event Ring/Answered on channel 1<br>
> [Sep 11 22:06:19] DEBUG[4759]: sig_analog.c:3621 analog_handle_init_event: channel (1) - signaling (5) - event (ANALOG_EVENT_RINGOFFHOOK)<br>
> [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<br>
> [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<br>
> [Sep 11 22:06:19] DEBUG[4759]: dsp.c:1576 ast_dsp_set_busy_pattern: dsp busy pattern set to 0,0<br>
> [Sep 11 22:06:19] DEBUG[4737]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1<br>
> [Sep 11 22:06:19] DEBUG[5414]: sig_analog.c:1769 __analog_ss_thread: __analog_ss_thread 1<br>
> -- Starting simple switch on 'DAHDI/1-1'<br>
> [Sep 11 22:06:19] DEBUG[4737]: devicestate.c:458 do_state_change: Changing state for DAHDI/1 - state 2 (In use)<br>
> [Sep 11 22:06:19] DEBUG[4737]: devicestate.c:438 devstate_event: device 'DAHDI/1' state '2'<br>
> [Sep 11 22:06:19] DEBUG[5414]: sig_analog.c:2392 __analog_ss_thread: Receiving DTMF cid on channel DAHDI/1-1<br>
> [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<br>
> member of any queue.<br>
> [Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:3509 analog_exception: analog_exception 1<br>
> [Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:3603 analog_exception: Exception on 16, channel 1<br>
> [Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:2660 __analog_handle_event: __analog_handle_event 1<br>
> [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)<br>
> [Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:3509 analog_exception: analog_exception 1<br>
> [Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:3603 analog_exception: Exception on 16, channel 1<br>
> [Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:2660 __analog_handle_event: __analog_handle_event 1<br>
> [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)<br>
> [Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:3043 __analog_handle_event: Ring detected<br>
> [Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:2441 __analog_ss_thread: CID got string ''<br>
> [Sep 11 22:06:21] DEBUG[5414]: callerid.c:207 callerid_get_dtmf: No cid detected<br>
> [Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:2443 __analog_ss_thread: CID is '', flags 8<br>
> [Sep 11 22:06:21] DEBUG[5414]: pbx.c:3239 ast_str_retrieve_variable: Result of 'EXTEN' is 's'<br>
> [Sep 11 22:06:21] DEBUG[4737]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1<br>
> [Sep 11 22:06:21] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: Launching 'NoOp'<br>
> [Sep 11 22:06:21] DEBUG[4737]: devicestate.c:458 do_state_change: Changing state for DAHDI/1 - state 2 (In use)<br>
> [Sep 11 22:06:21] DEBUG[4737]: devicestate.c:438 devstate_event: device 'DAHDI/1' state '2'<br>
> -- Executing [s@incoming:1] NoOp("DAHDI/1-1", "Incoming s") in new stack<br>
> [Sep 11 22:06:21] DEBUG[5414]: pbx.c:4058 pbx_substitute_variables_helper_full: Function result is ''<br>
> [Sep 11 22:06:21] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: Launching 'Verbose'<br>
> -- Executing [s@incoming:2] Verbose("DAHDI/1-1", "CID ") in new stack<br>
> CID<br>
> [Sep 11 22:06:21] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: Launching 'Set'<br>
> -- Executing [s@incoming:3] Set("DAHDI/1-1", "SPYGROUP=queue-01") in new stack<br>
> [Sep 11 22:06:21] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: Launching 'Answer'<br>
> -- Executing [s@incoming:4] Answer("DAHDI/1-1", "") in new stack<br>
> [Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:1499 analog_answer: analog_answer 1<br>
> [Sep 11 22:06:21] DEBUG[5414]: sig_analog.c:1530 analog_answer: Took DAHDI/1-1 off hook<br>
> [Sep 11 22:06:21] DEBUG[5414]: chan_dahdi.c:4927 dahdi_enable_ec: Enabled echo cancellation on channel 1<br>
> [Sep 11 22:06:21] DEBUG[4737]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1<br>
> [Sep 11 22:06:21] DEBUG[5414]: chan_dahdi.c:4946 dahdi_train_ec: No echo training requested<br>
> [Sep 11 22:06:21] DEBUG[5414]: chan_dahdi.c:9403 dahdi_indicate: Requested indication -1 on channel DAHDI/1-1<br>
> [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<br>
> member of any queue.<br>
> [Sep 11 22:06:21] DEBUG[4737]: devicestate.c:458 do_state_change: Changing state for DAHDI/1 - state 2 (In use)<br>
> [Sep 11 22:06:21] DEBUG[4737]: devicestate.c:438 devstate_event: device 'DAHDI/1' state '2'<br>
> [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<br>
> member of any queue.<br>
> [Sep 11 22:06:21] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: Launching 'AGI'<br>
> -- Executing [s@incoming:5] AGI("DAHDI/1-1", "/usr/local/lib/agi/office-hours.agi,custom/no-service") in new stack<br>
> -- Launched AGI Script /usr/local/lib/agi/office-hours.agi<br>
> > /usr/local/lib/agi/office-hours.agi,custom/no-service: FILE custom/no-service<br>
> /usr/local/lib/agi/office-hours.agi,custom/no-service: Week day 2<br>
> /usr/local/lib/agi/office-hours.agi,custom/no-service: OS: 36000, OE: 79200, CUR: 79581<br>
> -- AGI Script Executing Application: (Playback) Options: (custom/test)<br>
> [Sep 11 22:06:21] DEBUG[5414]: channel.c:5171 set_format: Set channel DAHDI/1-1 to write format slin<br>
> [Sep 11 22:06:21] DEBUG[5414]: channel.c:3506 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second<br>
> -- <DAHDI/1-1> Playing 'custom/test.slin' (language 'en')<br>
> [Sep 11 22:06:28] DEBUG[5414]: channel.c:3506 ast_settimeout: Scheduling timer at (52 requested / 52 actual) timer ticks per second<br>
> [Sep 11 22:06:28] DEBUG[5414]: channel.c:3506 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second<br>
> [Sep 11 22:06:28] DEBUG[5414]: channel.c:3506 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second<br>
> [Sep 11 22:06:28] DEBUG[5414]: channel.c:3506 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second<br>
> [Sep 11 22:06:28] DEBUG[5414]: channel.c:5171 set_format: Set channel DAHDI/1-1 to write format ulaw<br>
> -- <DAHDI/1-1>AGI Script /usr/local/lib/agi/office-hours.agi completed, returning 0<br>
> [Sep 11 22:06:28] DEBUG[5414]: pbx.c:3239 ast_str_retrieve_variable: Result of 'PASS' is '0'<br>
> [Sep 11 22:06:28] DEBUG[5414]: pbx.c:4126 pbx_substitute_variables_helper_full: Expression result is '1'<br>
> [Sep 11 22:06:28] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: Launching 'GotoIf'<br>
> -- Executing [s@incoming:6] GotoIf("DAHDI/1-1", "1 ?done") in new stack<br>
> -- Goto (incoming,s,12)<br>
> [Sep 11 22:06:28] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: Launching 'NoOp'<br>
> -- Executing [s@incoming:12] NoOp("DAHDI/1-1", "") in new stack<br>
> [Sep 11 22:06:28] DEBUG[5414]: pbx.c:4230 pbx_extension_helper: Launching 'Hangup'<br>
> -- Executing [s@incoming:13] Hangup("DAHDI/1-1", "") in new stack<br>
> [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'<br>
> == Spawn extension (incoming, s, 13) exited non-zero on 'DAHDI/1-1'<br>
> [Sep 11 22:06:28] DEBUG[5414]: channel.c:2683 ast_softhangup_nolock: Soft-Hanging up channel 'DAHDI/1-1'<br>
> [Sep 11 22:06:28] DEBUG[5414]: channel.c:2831 ast_hangup: Hanging up channel 'DAHDI/1-1'<br>
> [Sep 11 22:06:28] DEBUG[5414]: chan_dahdi.c:6149 dahdi_hangup: dahdi_hangup(DAHDI/1-1)<br>
> [Sep 11 22:06:28] DEBUG[5414]: sig_analog.c:1282 analog_hangup: analog_hangup 1<br>
> [Sep 11 22:06:28] DEBUG[5414]: sig_analog.c:1305 analog_hangup: Hangup: channel: 1 index = 0, normal = 1, callwait = 0, thirdcall = 0<br>
> [Sep 11 22:06:28] DEBUG[5414]: chan_dahdi.c:4962 dahdi_disable_ec: Disabled echo cancellation on channel 1<br>
> [Sep 11 22:06:28] DEBUG[5414]: chan_dahdi.c:6747 dahdi_setoption: Set option TONE VERIFY, mode: OFF(0) on DAHDI/1-1<br>
> [Sep 11 22:06:28] DEBUG[5414]: chan_dahdi.c:6757 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/1-1<br>
> [Sep 11 22:06:28] DEBUG[5414]: sig_analog.c:782 analog_update_conf: Updated conferencing on 1, with 0 conference users<br>
> -- Hanging up on 'DAHDI/1-1'<br>
> -- Hungup 'DAHDI/1-1'<br>
> [Sep 11 22:06:28] DEBUG[5414]: res_odbc.c:1050 odbc_release_obj2: odbc_release_obj2(0x7f537401ac78) called (obj->txf = (nil))<br>
> [Sep 11 22:06:28] DEBUG[5414]: cdr_radius.c:208 radius_log: Unable to create RADIUS record. CDR not recorded!<br>
> [Sep 11 22:06:28] DEBUG[5414]: res_config_sqlite.c:834 cdr_handler: SQL query: INSERT INTO ast_cdr<br>
> (dst,dcontext,channel,lastapp,start,answer,end,duration,billsec,disposition,amaflags,uniqueid) VALUES ('s','incoming','DAHDI/1-1','Hangup','2012-09-11<br>
> 22:06:19','2012-09-11 22:06:21','2012-09-11 22:06:28','9','7','ANSWERED','DOCUMENTATION','1347381379.5')<br>
> [Sep 11 22:06:28] DEBUG[4737]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1<br>
> [Sep 11 22:06:28] DEBUG[4737]: devicestate.c:458 do_state_change: Changing state for DAHDI/1 - state 0 (Unknown)<br>
> [Sep 11 22:06:28] DEBUG[4737]: devicestate.c:438 devstate_event: device 'DAHDI/1' state '0'<br>
> [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<br>
> a member of any queue.<br>
><br>
> Regards,<br>
><br>
> -- Raj<br>
<br>
<br>
--<br>
_____________________________________________________________________<br>
-- Bandwidth and Colocation Provided by <a href="http://www.api-digital.com" target="_blank">http://www.api-digital.com</a> --<br>
New to Asterisk? Join us for a live introductory webinar every Thurs:<br>
<a href="http://www.asterisk.org/hello" target="_blank">http://www.asterisk.org/hello</a><br>
<br>
asterisk-users mailing list<br>
To UNSUBSCRIBE or update options visit:<br>
<a href="http://lists.digium.com/mailman/listinfo/asterisk-users" target="_blank">http://lists.digium.com/mailman/listinfo/asterisk-users</a></blockquote></div>