This has been happening since the asterisk 1.2 days, makes me believe it has something to do with Analog FXO ckts provided.
Mitul Limbani On Sep 12, 2012 10:18 AM, "Vladimir Mikhelson" <[email protected]> wrote: > Raj, > > I am just confirming it happens here as well. > > CentOS 5.7. Asterisk 1.8.15.1. DAHDI 2.6.1. > > Digium, Inc. Wildcard TDM410 4-port analog card (rev 11) > > Loadzone = us > > The problem started manifesting itself after I switched to 1.8.x from > 1.6.2.x > > Typical scenario: a caller apparently hangs up, dial plan goes into > voice mail and records a 50 sec message with the CO tones. Then > something happens and the line finally gets hung up. > > Regards, > Vladimir > > > > > On 9/11/2012 12:08 PM, Raj Mathur (राज माथुर) wrote: > > 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@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@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@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@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@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@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@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@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 > > > -- > _____________________________________________________________________ > -- Bandwidth and Colocation Provided by http://www.api-digital.com -- > New to Asterisk? Join us for a live introductory webinar every Thurs: > http://www.asterisk.org/hello > > asterisk-users mailing list > To UNSUBSCRIBE or update options visit: > http://lists.digium.com/mailman/listinfo/asterisk-users
-- _____________________________________________________________________ -- Bandwidth and Colocation Provided by http://www.api-digital.com -- New to Asterisk? Join us for a live introductory webinar every Thurs: http://www.asterisk.org/hello asterisk-users mailing list To UNSUBSCRIBE or update options visit: http://lists.digium.com/mailman/listinfo/asterisk-users
