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

Tue Sep 11 23:57:54 CDT 2012

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" <vlad at mikhelson.com> 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 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
>
>
> --
> _____________________________________________________________________
> -- 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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20120912/0f30a1d8/attachment.htm>