[asterisk-r2] Clear Forward problem

Fri Aug 28 13:45:28 CDT 2009

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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.digium.com/pipermail/asterisk-r2/attachments/20090828/f98fcfed/attachment.htm 