[asterisk-r2] Clear Forward problem

Fri Aug 28 13:47:47 CDT 2009

Hi,
How often does this happens?

Which openr2 version is this? try latest 1.2.0rc2
http://openr2.googlecode.com/files/openr2-1.2.0rc2.tar.gz, starting with
1.2.0 I fixed a couple of race conditions that could cause this problem.

Also try compiling Asterisk without optimizations ( it seems the last stack
frames are inside asterisk, but  ??? means there is no stack information for
those frames ).

On Fri, Aug 28, 2009 at 2:45 PM, Rafael Prado Rocchi
<prado at practis.com.br>wrote:

>  Hello Moises,
>
>
>
> We are having a problem that “locks” some channels, precisely 15 channels
> when it occurs.
>
>
>
> Description:
>
> Asterisk originate the call
>
> The call gets answered
>
> Asterisk disconnect the call
>
> (asterisk 1.4.26)
>
>
>
>
>
> But from time to time, the channel can’t be used anymore. It stays in
> “Clear Forward” state. It can be seen below:
>
>
>
> 95 BR      10      4        Yes       No               CLEAR FO SEIZE AC
>
>
>
> When it occurs, the first 15 channels on the E1 gets this state. The last
> 15 channels work normally.
>
> We put an analyzer at the E1 and found that:
>
>
>
> The Clear forward is sent
>
> The ack is received
>
> The channel is released normally
>
>
>
> But asterisk “thinks” it is still in Clear Forward state, like if it was
> waiting for the ack.
>
>
>
> Since the hardware and the signaling are working ok, it seems that some
> internal flag remains at the old state. And that flag doesn’t allow asterisk
> to dial on these channels.
>
>
>
> This is a normal call:
>
>
>
> [16:12:57:551] [Thread: 1123551552] [Chan 120] - CAS Rx << [ANSWER] 0x04
>
> [16:12:57:551] [Thread: 1123551552] [Chan 120] - Attempting to cancel timer
> timer 3
>
> [16:12:57:551] [Thread: 1123551552] [Chan 120] - timer id 3 found,
> cancelling it now
>
> [16:12:57:551] [Thread: 1123551552] [Chan 120] - Attempting to cancel timer
> timer 0
>
> [16:12:57:551] [Thread: 1123551552] [Chan 120] - Cannot cancel timer 0
>
> [16:14:26:960] [Thread: 1123551552] [Chan 120] - Attempting to cancel timer
> timer 0
>
> [16:14:26:960] [Thread: 1123551552] [Chan 120] - Cannot cancel timer 0
>
> [16:14:26:960] [Thread: 1123551552] [Chan 120] - CAS Tx >> [CLEAR FORWARD]
> 0x08
>
> [16:14:26:960] [Thread: 1123551552] [Chan 120] - CAS Raw Tx >> 0x09
>
> [16:14:26:992] [Thread: 1093957952] [Chan 120] - Bits changed from 0x04 to
> 0x08
>
> [16:14:26:992] [Thread: 1093957952] [Chan 120] - CAS Rx << [IDLE] 0x08
>
> [16:14:26:992] [Thread: 1093957952] [Chan 120] - Call ended
>
> [16:14:26:992] [Thread: 1093957952] [Chan 120] - Attempting to cancel timer
> timer 0
>
> [16:14:26:992] [Thread: 1093957952] [Chan 120] - Cannot cancel timer 0
>
>
>
>
>
>
>
> This is the first problematic call: (at channel 1, span 4)
>
> After this, the channel locks in “CLEAR FO” state
>
>
>
> [14:46:55:584] [Thread: 1099430208] [Chan 94] - scheduled timer id 3
> (r2_answer)
>
> [14:47:04:857] [Thread: 1099430208] [Chan 94] - Bits changed from 0x0C to
> 0x04
>
> [14:47:04:857] [Thread: 1099430208] [Chan 94] - CAS Rx << [ANSWER] 0x04
>
> [14:47:04:857] [Thread: 1099430208] [Chan 94] - Attempting to cancel timer
> timer 3
>
> [14:47:04:857] [Thread: 1099430208] [Chan 94] - timer id 3 found,
> cancelling it now
>
> [14:47:04:857] [Thread: 1099430208] [Chan 94] - Attempting to cancel timer
> timer 0
>
> [14:47:04:857] [Thread: 1099430208] [Chan 94] - Cannot cancel timer 0
>
> [14:48:00:592] [Thread: 1099430208] [Chan 94] - Attempting to cancel timer
> timer 0
>
> [14:48:00:592] [Thread: 1099430208] [Chan 94] - Cannot cancel timer 0
>
> [14:48:00:592] [Thread: 1099430208] [Chan 94] - CAS Tx >> [CLEAR FORWARD]
> 0x08
>
> [14:48:00:592] [Thread: 1099430208] [Chan 94] - CAS Raw Tx >> 0x09
>
> [15:55:32:843] [Thread: 1146915136] [Chan 94] - Attempting to cancel timer
> timer 0
>
> [15:55:32:844] [Thread: 1146915136] [Chan 94] - Cannot cancel timer 0
>
>
>
>
>
> The logs of the ocurrency in other channels are incomplete as the the
> process that is loggin the call seems to be interrupted (the last line of
> the log is incomplete, the log is stoped at the middle of the line.
>
>
>
>
>
>
>
>
>
>
>
> We got 3 dumps too:
>
>
>
>
> 1)
>
> (gdb) bt
>
> #0  0x0000000000000000 in ?? ()
>
> #1  0x00000036af6038c5 in openr2_chan_handle_timers (r2chan=0xf8ec000) at
> r2chan.c:318
>
> #2  0x00000036af6038f6 in openr2_chan_process_event (r2chan=0xf8ec000) at
> r2chan.c:331
>
> #3  0x00002aaaba885f3c in mfcr2_monitor (data=<value optimized out>) at
> chan_dahdi.c:9241
>
> #4  0x00000000004aff7c in dummy_start (data=<value optimized out>) at
> utils.c:856
>
> #5  0x0000003f32606307 in start_thread () from /lib64/libpthread.so.0
>
> #6  0x0000003f31ad1ded in clone () from /lib64/libc.so.6
>
>
>
>
>
> 2)
>
> #0  0x0000000000000000 in ?? ()
>
> (gdb) bt
>
> #0  0x0000000000000000 in ?? ()
>
> #1  0x00000036af6038c5 in openr2_chan_handle_timers (r2chan=0x2aaaac070fe0)
> at r2chan.c:318
>
> #2  0x00000036af6038f6 in openr2_chan_process_event (r2chan=0x2aaaac070fe0)
> at r2chan.c:331
>
> #3  0x00002aaaba93407c in dahdi_func_read (chan=0x2aaaac070fe0,
> function=<value optimized out>, data=0x0,
>
>     buf=0x36af6086db "H\211\225øþÿÿH\213\205\bÿÿÿH\213\200", len=0) at
> chan_dahdi.c:3933
>
> #4  0x0000000000000013 in ?? ()
>
> #5  0x0000000000000014 in ?? ()
>
> #6  0x0000000000000016 in ?? ()
>
> #7  0x0000000000000017 in ?? ()
>
> #8  0x0000000000000018 in ?? ()
>
> #9  0x0000000000000019 in ?? ()
>
> #10 0x000000000000001a in ?? ()
>
> #11 0x000000000000001b in ?? ()
>
> #12 0x000000000000001c in ?? ()
>
> #13 0x000000000000001d in ?? ()
>
> #14 0x000000000000001e in ?? ()
>
> #15 0x000000000000001f in ?? ()
>
> #16 0x0002000300000020 in ?? ()
>
> #17 0x0000000000000021 in ?? ()
>
> #18 0x0000000000000022 in ?? ()
>
> #19 0x0000000000000000 in ?? ()
>
>
>
>
>
> 3)
>
> (gdb) bt
>
> #0  0x00000036af608f40 in set_cas_signal (r2chan=0x7c171c0,
> signal=OR2_CAS_CLEAR_FORWARD) at r2proto.c:324
>
> #1  0x00000036af60e777 in send_clear_forward (r2chan=0x7c171c0) at
> r2proto.c:2397
>
> #2  0x00000036af60e8cd in openr2_proto_disconnect_call (r2chan=0x7c171c0,
> cause=OR2_CAUSE_NORMAL_CLEARING) at r2proto.c:2460
>
> #3  0x00000036af60477d in openr2_chan_disconnect_call (r2chan=0x7c171c0,
> cause=OR2_CAUSE_NORMAL_CLEARING) at r2chan.c:609
>
> #4  0x00002aaaba8a89a6 in dahdi_hangup (ast=0x7eb86a0) at chan_dahdi.c:3344
>
> #5  0x000000000043ccb2 in ast_hangup (chan=0x7eb86a0) at channel.c:1548
>
> #6  0x00002aaaacd3f6d9 in dial_exec_full (chan=0x2aaac4145930, data=<value
> optimized out>, peerflags=0x44bf2560, continue_exec=0x0) at app_dial.c:1822
>
> #7  0x00002aaaacd42a55 in dial_exec (chan=0x0, data=0x4004da2b) at
> app_dial.c:1854
>
> #8  0x00000000004811cd in pbx_extension_helper (c=0x2aaac4145930,
> con=<value optimized out>, context=0x2aaac4145b80
> "macro-disca-ddd-telefonica",
>
>     exten=0x2aaac4145bd0 "s", priority=8, label=<value optimized out>,
> callerid=0x2aaac4110790 "", action=E_SPAWN) at pbx.c:538
>
> #9  0x0000000000481603 in ast_spawn_extension (c=0x0, context=0x16 <Address
> 0x16 out of bounds>,
>
>     exten=0xffffffffffffffb0 <Address 0xffffffffffffffb0 out of bounds>,
> priority=775435825, callerid=<value optimized out>) at pbx.c:2285
>
> #10 0x00002aaabc7c581a in _macro_exec (chan=0x2aaac4145930, data=<value
> optimized out>, exclusive=0) at app_macro.c:352
>
> #11 0x00000000004811cd in pbx_extension_helper (c=0x2aaac4145930,
> con=<value optimized out>, context=0x2aaac4145b80
> "macro-disca-ddd-telefonica",
>
>     exten=0x2aaac4145bd0 "s", priority=1, label=<value optimized out>,
> callerid=0x2aaac4110790 "", action=E_SPAWN) at pbx.c:538
>
> #12 0x0000000000483852 in __ast_pbx_run (c=0x2aaac4145930) at pbx.c:2285
>
> #13 0x0000000000484719 in pbx_thread (data=0x0) at pbx.c:2602
>
> #14 0x00000000004aff7c in dummy_start (data=<value optimized out>) at
> utils.c:856
>
> #15 0x0000003f32606307 in start_thread () from /lib64/libpthread.so.0
>
> #16 0x0000003f31ad1ded in clone () from /lib64/libc.so.6
>
>
>
>
>
>
>
> This is only occurring with “Telefonica E1s”. Can it be a configuration
> problem?
>
>
>
> I’ll wait your analysis,
>
> Thanks,
>
> Prado
>
>
>
>
>
>
>
>
>
>
>
>
>
> _______________________________________________
> --Bandwidth and Colocation Provided by http://www.api-digital.com--
>
> asterisk-r2 mailing list
> To UNSUBSCRIBE or update options visit:
>   http://lists.digium.com/mailman/listinfo/asterisk-r2
>

-- 
Moises Silva
Software Developer
Sangoma Technologies Inc. | 50 McIntosh Drive, Suite 120, Markham ON L3R 9T3
Canada
t. 1 905 474 1990 x 128 | e. moy at sangoma.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.digium.com/pipermail/asterisk-r2/attachments/20090828/2a9182e0/attachment-0001.htm 