mfcr2 channel state IDLE 0x00 and call trace log file not ended ??

Home » Asterisk Users » mfcr2 channel state IDLE 0x00 and call trace log file not ended ??
Asterisk Users No Comments

Hi, would be glad to be contributing with this question to all the comunity.

I´m having a weird issue, suddenly I get Channels on IDLE
0x00 state until I do a dahdi restart.

Trying to do a call trace to see whats going on deeper, I get surprised when tried to open the .call file to see the log this is incomplete.

This is what I see

[root@localhost telefonica]# nano chan-9-backward-804-20130507123100.call
…..

[12:31:01:846] [Thread:
3067460464] [Chan 9] – Getting ANI digit 3
[12:31:01:846] [Thread:
3067460464] [Chan 9] – ANI so far: 1152723, expected length:
10
[12:31:01:846] [Thread: 3067460464] [Chan 9] – MF Tx >> 5
[ON]
[12:31:01:846] [Thread: 3067460464] [Chan 9] – scheduled timer id
13 (mf_back_cycle)
[12:31:01:906]

(I deleted the first part just for being more readable, but I didnt deleted the end its just has its end was somehow incomplete.

this is what I get from other call in the same situation.

[12:30:57:242] [Thread: 3067214704] [Chan 12] – MF Rx << 6 [OFF] [12:30:57:242] [Thread: 3067214704] [Chan 12] - MF Tx >> 5
[OFF]
[12:30:57:302] [Thread: 3067214704] [Chan 12] – MF Rx << 7 [ON] [12:30:57:302] [Thread: 3067214704] [Chan 12] - Attempting to cancel timer time$ [12:30:57:302] [Thread: 3067214704] [Chan 12] - timer id 12 found, cancelling i$ [12:30:57:302] [Thread: 3067214704] [Chan 12] - Getting ANI digit 7 [12:30:57:302] [Thread: 3067214704] [Chan 12] - ANI so far: 1148567, expected l$ [12:30:57:302] [Thread: 3067214704] [Chan 12] - MF T just like “cutted” but then I found some complete logs of those same “RX: 0x00 state” calls… cat chan-30-backward-428-20130514144454.call …… [14:44:56:300] [Thread: 3067771760] [Chan 30] – Getting ANI digit 1 [14:44:56:300] [Thread: 3067771760] [Chan 30] – ANI so far: 1145043471, expected length: 10 [14:44:56:300] [Thread: 3067771760] [Chan 30] – Done getting ANI! [14:44:56:300] [Thread: 3067771760] [Chan 30] – Requesting change to Group II with signal 0x33 [14:44:56:300] [Thread: 3067771760] [Chan 30] – MF Tx >> 3 [ON]
[14:44:56:300] [Thread: 3067771760] [Chan 30] –
scheduled timer id 16 (mf_back_cycle)
[14:44:56:360] [Thread:
3067771760] [Chan 30] – MF Rx << 1 [OFF] [14:44:56:360] [Thread: 3067771760] [Chan 30] - MF Tx >> 3 [OFF]
[14:44:56:420] [Thread:
3067771760] [Chan 30] – MF Rx << 1 [ON] [14:44:56:420] [Thread: 3067771760] [Chan 30] - Attempting to cancel timer timer 16 [14:44:56:420] [Thread: 3067771760] [Chan 30] - timer id 16 found, cancelling it now [14:44:56:420] [Thread: 3067771760] [Chan 30] - MF Tx [14:44:56:420] [Thread: 3067771760] [Chan 30] - scheduled timer id 17 (mf_back_cycle) [14:44:56:480] [Thread: 3067771760] [Chan 30] - MF Rx << 1 [OFF] [14:44:56:480] [Thread: 3067771760] [Chan 30] - MF Tx >> 6 [OFF]
[14:44:56:480] [Thread: 3067771760] [Chan 30] –
Attempting to cancel timer timer 17
[14:44:56:480] [Thread: 3067771760]
[Chan 30] – timer id 17 found, cancelling it now
[14:44:56:480] [Thread:
3067771760] [Chan 30] – scheduled timer id 18
(r2_answer_delay)
[14:44:56:640] [Thread: 3067771760] [Chan 30] –
Attempting to cancel timer timer 18
[14:44:56:640] [Thread: 3067771760]
[Chan 30] – timer id 18 found, cancelling it now
[14:44:56:640] [Thread:
3067771760] [Chan 30] – calling timer 18 (r2_answer_delay)
callback
[14:45:12:244] [Thread: 3052403568] [Chan 30] – CAS Tx >>
[ANSWER] 0x04
[14:45:12:244] [Thread: 3052403568] [Chan 30] – CAS Raw Tx
[14:50:53:853] [Thread: 3052403568] [Chan 30] – Attempting to cancel timer timer 0
[14:50:53:853] [Thread: 3052403568] [Chan 30] –
Cannot cancel timer 0
[14:50:53:853] [Thread: 3052403568] [Chan 30] –
CAS Tx >> [CLEAR BACK] 0x0C
[14:50:53:853] [Thread: 3052403568] [Chan
30] – CAS Raw Tx >> 0x0D

and the same for this other channel..

….

[14:50:22:417] [Thread: 3067771760] [Chan 31] – Attempting to cancel timer timer 18
[14:50:22:417] [Thread: 3067771760] [Chan 31] – timer id
18 found, cancelling it now
[14:50:22:417] [Thread: 3067771760] [Chan
31] – calling timer 18 (r2_answer_delay) callback
[14:50:22:418]
[Thread: 3055217520] [Chan 31] – CAS Tx >> [ANSWER] 0x04
[14:50:22:418]
[Thread: 3055217520] [Chan 31] – CAS Raw Tx >> 0x05
[14:50:54:194]
[Thread: 3055217520] [Chan 31] – Attempting to cancel timer timer
0
[14:50:54:194] [Thread: 3055217520] [Chan 31] – Cannot cancel timer
0
[14:50:54:194] [Thread: 3055217520] [Chan 31] – CAS Tx >> [CLEAR BACK]
0x0C
[14:50:54:194] [Thread: 3055217520] [Chan 31] – CAS Raw Tx >> 0x0D

Is this call ended normally? Could it be an irq or hardware issue? Its happens only in the first port, which is connected to the teco, but the
2nd port which is connected to a samsung pbx didn´t get problems. Would be glad if anybody put some light on it.

By the way this is my configuration:

Asterisk 10.5.0 (but also tried in 1.8 and 1.6 with the same results)

HP ML110 G7 server

lspci -v

..

0e:08.0
Communication controller: Digium, Inc. Wildcard TE210P/TE212P dual-span T1/E1/J1 card 3.3V (rev 02)
Subsystem: Device 0003:0000
Flags: bus master, medium devsel, latency 64, IRQ 11
Memory at fbff0000 (32-bit, non-prefetchable) [size8]
Kernel driver in use: wct4xxp Kernel modules: wct4xxp

..

cat
/etc/dahdi/system.conf

span=1,1,0,cas,hdb3
cas=1-15,17-31:1101

span=2,0,0,cas,hdb3
cas2-46,48-62:1101
echocanceller=mg2,32-46,48-62

loadzone = ve defaultzone = ve

nano /etc/asterisk/chan_dahdi.conf

resetinterval=never context=from-pstn group=0
;mfcr2_forced_release=yes mfcr2_logdir=telefonica mfcr2_logging=all mfcr2_call_files=yes echocancel=yes language=es signalling=mfcr2
mfcr2_variant=itu mfcr2_get_ani_first=no mfcr2_max_ani

mfcr2_max_dnis=4
mfcr2_category=national_subscriber
;mfcr2_mfback_timeout=-1
mfcr2_metering_pulse_timeoutP0
mfcr2_mfback_timeout