[asterisk-r2] RES: asterisk-r2 Digest, Vol 8, Issue 46

Wed Apr 22 14:40:56 CDT 2009

Moy,

After Who I installed the branch of openr2, occurred the following:

 - I called the extension 7320:

[Apr 22 12:23:14] NOTICE[2772]: chan_dahdi.c:1023 dahdi_r2_on_call_init:
New MFC/R2 call detected on chan 25.
[Apr 22 12:23:16] NOTICE[2772]: chan_dahdi.c:1090
dahdi_r2_on_call_offered: MFC/R2 call offered on chan 25. ANI =
113010XX00, DNIS = 7000, Category = National Subscriber
[Apr 22 12:23:17] NOTICE[2772]: chan_dahdi.c:1153
dahdi_r2_on_call_accepted: MFC/R2 call has been accepted on chan 25
    -- Executing [7000 at e1:1] Set("Zap/25-1", "CALLERID(num)=113010XX00")
in new stack
    -- Executing [7000 at e1:2] Dial("Zap/25-1",
"IAX2/astpstnr2:passwd at 172.16.78.XXX/7000") in new stack
    -- Called astpstnr2:passwd at 172.16.78.XXX/7000
    -- Call accepted by 172.16.78.XXX (format ulaw)
    -- Format for call is ulaw

 - And the log is this:
[12:23:14:812] [Thread: 3069750192] [Chan 25] - Call started at Wed Apr
22 12:23:14 2009 on chan 25
[12:23:14:812] [Thread: 3069750192] [Chan 25] - CAS Tx >> [SEIZE ACK]
0x0C
[12:23:14:812] [Thread: 3069750192] [Chan 25] - CAS Raw Tx >> 0x0D
[12:23:14:871] [Thread: 3069750192] [Chan 25] - MF Rx << 7 [ON]
[12:23:14:871] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 0
[12:23:14:871] [Thread: 3069750192] [Chan 25] - Cannot cancel timer 0
[12:23:14:871] [Thread: 3069750192] [Chan 25] - Getting DNIS digit 7
[12:23:14:871] [Thread: 3069750192] [Chan 25] - DNIS so far: 7, expected
length: 20
[12:23:14:871] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:14:871] [Thread: 3069750192] [Chan 25] - scheduled timer id 2
(mf_back_cycle)
[12:23:14:911] [Thread: 3069750192] [Chan 25] - MF Rx << 7 [OFF]
[12:23:14:911] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:14:991] [Thread: 3069750192] [Chan 25] - MF Rx << 1 [ON]
[12:23:14:991] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 2
[12:23:14:991] [Thread: 3069750192] [Chan 25] - timer id 2 found,
cancelling it now
[12:23:14:991] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:14:991] [Thread: 3069750192] [Chan 25] - scheduled timer id 3
(mf_back_cycle)
[12:23:15:051] [Thread: 3069750192] [Chan 25] - MF Rx << 1 [OFF]
[12:23:15:051] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:15:111] [Thread: 3069750192] [Chan 25] - MF Rx << 1 [ON]
[12:23:15:111] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 3
[12:23:15:111] [Thread: 3069750192] [Chan 25] - timer id 3 found,
cancelling it now
[12:23:15:111] [Thread: 3069750192] [Chan 25] - Getting ANI digit 1
[12:23:15:111] [Thread: 3069750192] [Chan 25] - ANI so far: 1, expected
length: 20
[12:23:15:111] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:15:111] [Thread: 3069750192] [Chan 25] - scheduled timer id 4
(mf_back_cycle)
[12:23:15:171] [Thread: 3069750192] [Chan 25] - MF Rx << 1 [OFF]
[12:23:15:171] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:15:231] [Thread: 3069750192] [Chan 25] - MF Rx << 1 [ON]
[12:23:15:231] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 4
[12:23:15:231] [Thread: 3069750192] [Chan 25] - timer id 4 found,
cancelling it now
[12:23:15:231] [Thread: 3069750192] [Chan 25] - Getting ANI digit 1
[12:23:15:231] [Thread: 3069750192] [Chan 25] - ANI so far: 11, expected
length: 20
[12:23:15:231] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:15:231] [Thread: 3069750192] [Chan 25] - scheduled timer id 5
(mf_back_cycle)
[12:23:15:311] [Thread: 3069750192] [Chan 25] - MF Rx << 1 [OFF]
[12:23:15:311] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:15:371] [Thread: 3069750192] [Chan 25] - MF Rx << 3 [ON]
[12:23:15:371] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 5
[12:23:15:371] [Thread: 3069750192] [Chan 25] - timer id 5 found,
cancelling it now
[12:23:15:371] [Thread: 3069750192] [Chan 25] - Getting ANI digit 3
[12:23:15:371] [Thread: 3069750192] [Chan 25] - ANI so far: 113,
expected length: 20
[12:23:15:371] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:15:371] [Thread: 3069750192] [Chan 25] - scheduled timer id 6
(mf_back_cycle)
[12:23:15:431] [Thread: 3069750192] [Chan 25] - MF Rx << 3 [OFF]
[12:23:15:431] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:15:491] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [ON]
[12:23:15:491] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 6
[12:23:15:491] [Thread: 3069750192] [Chan 25] - timer id 6 found,
cancelling it now
[12:23:15:491] [Thread: 3069750192] [Chan 25] - Getting ANI digit 0
[12:23:15:491] [Thread: 3069750192] [Chan 25] - ANI so far: 1130,
expected length: 20
[12:23:15:491] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:15:491] [Thread: 3069750192] [Chan 25] - scheduled timer id 7
(mf_back_cycle)
[12:23:15:551] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [OFF]
[12:23:15:551] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:15:611] [Thread: 3069750192] [Chan 25] - MF Rx << 1 [ON]
[12:23:15:611] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 7
[12:23:15:611] [Thread: 3069750192] [Chan 25] - timer id 7 found,
cancelling it now
[12:23:15:611] [Thread: 3069750192] [Chan 25] - Getting ANI digit 1
[12:23:15:611] [Thread: 3069750192] [Chan 25] - ANI so far: 11301,
expected length: 20
[12:23:15:611] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:15:611] [Thread: 3069750192] [Chan 25] - scheduled timer id 8
(mf_back_cycle)
[12:23:15:671] [Thread: 3069750192] [Chan 25] - MF Rx << 1 [OFF]
[12:23:15:671] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:15:731] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [ON]
[12:23:15:731] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 8
[12:23:15:731] [Thread: 3069750192] [Chan 25] - timer id 8 found,
cancelling it now
[12:23:15:731] [Thread: 3069750192] [Chan 25] - Getting ANI digit 0
[12:23:15:731] [Thread: 3069750192] [Chan 25] - ANI so far: 113010,
expected length: 20
[12:23:15:731] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:15:731] [Thread: 3069750192] [Chan 25] - scheduled timer id 9
(mf_back_cycle)
[12:23:15:791] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [OFF]
[12:23:15:791] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:15:851] [Thread: 3069750192] [Chan 25] - MF Rx << 3 [ON]
[12:23:15:851] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 9
[12:23:15:851] [Thread: 3069750192] [Chan 25] - timer id 9 found,
cancelling it now
[12:23:15:851] [Thread: 3069750192] [Chan 25] - Getting ANI digit X -
("modified for security")
[12:23:15:851] [Thread: 3069750192] [Chan 25] - ANI so far: 113010X,
expected length: 20
[12:23:15:851] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:15:851] [Thread: 3069750192] [Chan 25] - scheduled timer id 10
(mf_back_cycle)
[12:23:15:911] [Thread: 3069750192] [Chan 25] - MF Rx << 3 [OFF]
[12:23:15:911] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:15:971] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [ON]
[12:23:15:971] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 10
[12:23:15:971] [Thread: 3069750192] [Chan 25] - timer id 10 found,
cancelling it now
[12:23:15:971] [Thread: 3069750192] [Chan 25] - Getting ANI digit X -
("modified for security")
[12:23:15:971] [Thread: 3069750192] [Chan 25] - ANI so far: 113010XX,
expected length: 20
[12:23:15:971] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:15:971] [Thread: 3069750192] [Chan 25] - scheduled timer id 11
(mf_back_cycle)
[12:23:16:031] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [OFF]
[12:23:16:031] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:16:091] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [ON]
[12:23:16:091] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 11
[12:23:16:091] [Thread: 3069750192] [Chan 25] - timer id 11 found,
cancelling it now
[12:23:16:091] [Thread: 3069750192] [Chan 25] - Getting ANI digit 0
[12:23:16:091] [Thread: 3069750192] [Chan 25] - ANI so far: 113010XX0,
expected length: 20
[12:23:16:091] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:16:091] [Thread: 3069750192] [Chan 25] - scheduled timer id 12
(mf_back_cycle)
[12:23:16:151] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [OFF]
[12:23:16:151] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:16:211] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [ON]
[12:23:16:211] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 12
[12:23:16:211] [Thread: 3069750192] [Chan 25] - timer id 12 found,
cancelling it now
[12:23:16:211] [Thread: 3069750192] [Chan 25] - Getting ANI digit 0
[12:23:16:211] [Thread: 3069750192] [Chan 25] - ANI so far: 113010XX00,
expected length: 20
[12:23:16:211] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [ON]
[12:23:16:211] [Thread: 3069750192] [Chan 25] - scheduled timer id 13
(mf_back_cycle)
[12:23:16:271] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [OFF]
[12:23:16:271] [Thread: 3069750192] [Chan 25] - MF Tx >> 5 [OFF]
[12:23:16:331] [Thread: 3069750192] [Chan 25] - MF Rx << F [ON]
[12:23:16:331] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 13
[12:23:16:331] [Thread: 3069750192] [Chan 25] - timer id 13 found,
cancelling it now
[12:23:16:331] [Thread: 3069750192] [Chan 25] - Got end of ANI
[12:23:16:331] [Thread: 3069750192] [Chan 25] - Requesting next DNIS
with signal 0x31.
[12:23:16:331] [Thread: 3069750192] [Chan 25] - MF Tx >> 1 [ON]
[12:23:16:331] [Thread: 3069750192] [Chan 25] - scheduled timer id 14
(mf_back_cycle)
[12:23:16:391] [Thread: 3069750192] [Chan 25] - MF Rx << F [OFF]
[12:23:16:391] [Thread: 3069750192] [Chan 25] - MF Tx >> 1 [OFF]
[12:23:16:451] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [ON]
[12:23:16:451] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 14
[12:23:16:451] [Thread: 3069750192] [Chan 25] - timer id 14 found,
cancelling it now
[12:23:16:451] [Thread: 3069750192] [Chan 25] - Getting DNIS digit 0
[12:23:16:451] [Thread: 3069750192] [Chan 25] - DNIS so far: 70,
expected length: 20
[12:23:16:451] [Thread: 3069750192] [Chan 25] - Requesting next DNIS
with signal 0x31.
[12:23:16:451] [Thread: 3069750192] [Chan 25] - MF Tx >> 1 [ON]
[12:23:16:451] [Thread: 3069750192] [Chan 25] - scheduled timer id 15
(mf_back_cycle)
[12:23:16:511] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [OFF]
[12:23:16:511] [Thread: 3069750192] [Chan 25] - MF Tx >> 1 [OFF]
[12:23:16:571] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [ON]
[12:23:16:571] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 15
[12:23:16:571] [Thread: 3069750192] [Chan 25] - timer id 15 found,
cancelling it now
[12:23:16:571] [Thread: 3069750192] [Chan 25] - Getting DNIS digit 0
[12:23:16:571] [Thread: 3069750192] [Chan 25] - DNIS so far: 700,
expected length: 20
[12:23:16:571] [Thread: 3069750192] [Chan 25] - Requesting next DNIS
with signal 0x31.
[12:23:16:571] [Thread: 3069750192] [Chan 25] - MF Tx >> 1 [ON]
[12:23:16:571] [Thread: 3069750192] [Chan 25] - scheduled timer id 16
(mf_back_cycle)
[12:23:16:631] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [OFF]
[12:23:16:631] [Thread: 3069750192] [Chan 25] - MF Tx >> 1 [OFF]
[12:23:16:691] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [ON]
[12:23:16:691] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 16
[12:23:16:691] [Thread: 3069750192] [Chan 25] - timer id 16 found,
cancelling it now
[12:23:16:691] [Thread: 3069750192] [Chan 25] - Getting DNIS digit 0
[12:23:16:691] [Thread: 3069750192] [Chan 25] - DNIS so far: 7000,
expected length: 20
[12:23:16:691] [Thread: 3069750192] [Chan 25] - User requested us to
stop getting DNIS!
[12:23:16:691] [Thread: 3069750192] [Chan 25] - Requesting change to
Group II with signal 0x33
[12:23:16:691] [Thread: 3069750192] [Chan 25] - MF Tx >> 3 [ON]
[12:23:16:691] [Thread: 3069750192] [Chan 25] - scheduled timer id 17
(mf_back_cycle)
[12:23:16:751] [Thread: 3069750192] [Chan 25] - MF Rx << 0 [OFF]
[12:23:16:751] [Thread: 3069750192] [Chan 25] - MF Tx >> 3 [OFF]
[12:23:16:811] [Thread: 3069750192] [Chan 25] - MF Rx << 1 [ON]
[12:23:16:811] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 17
[12:23:16:811] [Thread: 3069750192] [Chan 25] - timer id 17 found,
cancelling it now
[12:23:16:811] [Thread: 3069750192] [Chan 25] - MF Tx >> 1 [ON]
[12:23:16:811] [Thread: 3069750192] [Chan 25] - scheduled timer id 18
(mf_back_cycle)
[12:23:16:871] [Thread: 3069750192] [Chan 25] - MF Rx << 1 [OFF]
[12:23:16:871] [Thread: 3069750192] [Chan 25] - MF Tx >> 1 [OFF]
[12:23:16:871] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 18
[12:23:16:871] [Thread: 3069750192] [Chan 25] - timer id 18 found,
cancelling it now
[12:23:16:871] [Thread: 3069750192] [Chan 25] - scheduled timer id 19
(r2_answer_delay)
[12:23:17:031] [Thread: 3069750192] [Chan 25] - Attempting to cancel
timer timer 19
[12:23:17:031] [Thread: 3069750192] [Chan 25] - timer id 19 found,
cancelling it now
[12:23:17:031] [Thread: 3069750192] [Chan 25] - calling timer 19
(r2_answer_delay) callback
[12:23:18:608] [Thread: 3068226480] [Chan 25] - CAS Tx >> [ANSWER] 0x04
[12:23:18:608] [Thread: 3068226480] [Chan 25] - CAS Raw Tx >> 0x05
[12:23:37:643] [Thread: 3068226480] [Chan 25] - Bits changed from 0x00
to 0x08
[12:23:37:643] [Thread: 3068226480] [Chan 25] - CAS Rx << [CLEAR
FORWARD] 0x08
[12:23:37:643] [Thread: 3068226480] [Chan 25] - scheduled timer id 20
(r2_metering_pulse_fwd)
[12:23:37:659] [Thread: 3068226480] [Chan 25] - Bits changed from 0x08
to 0x00
[12:23:37:659] [Thread: 3068226480] [Chan 25] - CAS Rx << [0x00] 0x00
[12:23:37:659] [Thread: 3068226480] [Chan 25] - Protocol error. Reason =
Invalid CAS, R2 State = Clear Forward Received, MF state = MF Engine
Off, MF Group = Backward Group B, CAS = 0x00
DNIS = 7000, ANI = 113010XX00, MF = 0x20
[12:23:37:659] [Thread: 3068226480] [Chan 25] - Attempting to cancel
timer timer 0
[12:23:37:659] [Thread: 3068226480] [Chan 25] - Cannot cancel timer 0

 - After, the call is dropped.

In another call, occurred this:
[Apr 22 12:50:09] NOTICE[2771]: chan_dahdi.c:1023 dahdi_r2_on_call_init:
New MFC/R2 call detected on chan 14.
[Apr 22 12:50:11] NOTICE[2771]: chan_dahdi.c:1090
dahdi_r2_on_call_offered: MFC/R2 call offered on chan 14. ANI =
113010XX00, DNIS = 7000, Category = National Subscriber
[Apr 22 12:50:11] NOTICE[2771]: chan_dahdi.c:1153
dahdi_r2_on_call_accepted: MFC/R2 call has been accepted on chan 14
    -- Executing [7000 at e1:1] Set("Zap/14-1", "CALLERID(num)=113010XX00")
in new stack
    -- Executing [7000 at e1:2] Dial("Zap/14-1",
"IAX2/astpstnr2:passwd at 172.16.78.XXX/7000") in new stack
    -- Called astpstnr2:passwd at 172.16.78.XXX/7000
    -- Call accepted by 172.16.78.XXX (format ulaw)
    -- Format for call is ulaw
    -- IAX2/172.16.78.XXX:4569-965 is ringing
    -- IAX2/172.16.78.XXX:4569-965 stopped sounds
    -- IAX2/172.16.78.XXX:4569-965 answered Zap/14-1
[Apr 22 12:50:17] ERROR[2870]: chan_dahdi.c:1294 dahdi_r2_write_log:
Chan 14 - Protocol error. Reason = Invalid CAS, R2 State = Answer
Transmitted, MF state = MF Engine Off, MF Group = Backward Group B, CAS
= 0x04
DNIS = 7000, ANI = 113010XX00, MF = 0x20
[Apr 22 12:50:17] ERROR[2870]: chan_dahdi.c:1058
dahdi_r2_on_protocol_error: MFC/R2 protocol error on chan 14: Invalid
CAS
    -- Hungup 'IAX2/172.16.78.XXX:4569-965'
  == Spawn extension (e1, 7000, 2) exited non-zero on 'Zap/14-1'
    -- Hungup 'Zap/14-1'

 - And the log is this:
[12:50:09:408] [Thread: 3069995952] [Chan 14] - Call started at Wed Apr
22 12:50:09 2009 on chan 14
[12:50:09:408] [Thread: 3069995952] [Chan 14] - CAS Tx >> [SEIZE ACK]
0x0C
[12:50:09:408] [Thread: 3069995952] [Chan 14] - CAS Raw Tx >> 0x0D
[12:50:09:474] [Thread: 3069995952] [Chan 14] - MF Rx << 7 [ON]
[12:50:09:474] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 0
[12:50:09:474] [Thread: 3069995952] [Chan 14] - Cannot cancel timer 0
[12:50:09:474] [Thread: 3069995952] [Chan 14] - Getting DNIS digit 7
[12:50:09:474] [Thread: 3069995952] [Chan 14] - DNIS so far: 7, expected
length: 20
[12:50:09:474] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:09:474] [Thread: 3069995952] [Chan 14] - scheduled timer id 2
(mf_back_cycle)
[12:50:09:554] [Thread: 3069995952] [Chan 14] - MF Rx << 7 [OFF]
[12:50:09:554] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:09:614] [Thread: 3069995952] [Chan 14] - MF Rx << 1 [ON]
[12:50:09:614] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 2
[12:50:09:614] [Thread: 3069995952] [Chan 14] - timer id 2 found,
cancelling it now
[12:50:09:614] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:09:614] [Thread: 3069995952] [Chan 14] - scheduled timer id 3
(mf_back_cycle)
[12:50:09:694] [Thread: 3069995952] [Chan 14] - MF Rx << 1 [OFF]
[12:50:09:694] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:09:754] [Thread: 3069995952] [Chan 14] - MF Rx << 1 [ON]
[12:50:09:754] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 3
[12:50:09:754] [Thread: 3069995952] [Chan 14] - timer id 3 found,
cancelling it now
[12:50:09:754] [Thread: 3069995952] [Chan 14] - Getting ANI digit 1
[12:50:09:754] [Thread: 3069995952] [Chan 14] - ANI so far: 1, expected
length: 20
[12:50:09:754] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:09:754] [Thread: 3069995952] [Chan 14] - scheduled timer id 4
(mf_back_cycle)
[12:50:09:834] [Thread: 3069995952] [Chan 14] - MF Rx << 1 [OFF]
[12:50:09:834] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:09:894] [Thread: 3069995952] [Chan 14] - MF Rx << 1 [ON]
[12:50:09:894] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 4
[12:50:09:894] [Thread: 3069995952] [Chan 14] - timer id 4 found,
cancelling it now
[12:50:09:894] [Thread: 3069995952] [Chan 14] - Getting ANI digit 1
[12:50:09:894] [Thread: 3069995952] [Chan 14] - ANI so far: 11, expected
length: 20
[12:50:09:894] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:09:894] [Thread: 3069995952] [Chan 14] - scheduled timer id 5
(mf_back_cycle)
[12:50:09:974] [Thread: 3069995952] [Chan 14] - MF Rx << 1 [OFF]
[12:50:09:974] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:10:034] [Thread: 3069995952] [Chan 14] - MF Rx << 3 [ON]
[12:50:10:034] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 5
[12:50:10:034] [Thread: 3069995952] [Chan 14] - timer id 5 found,
cancelling it now
[12:50:10:034] [Thread: 3069995952] [Chan 14] - Getting ANI digit 3
[12:50:10:034] [Thread: 3069995952] [Chan 14] - ANI so far: 113,
expected length: 20
[12:50:10:034] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:10:034] [Thread: 3069995952] [Chan 14] - scheduled timer id 6
(mf_back_cycle)
[12:50:10:094] [Thread: 3069995952] [Chan 14] - MF Rx << 3 [OFF]
[12:50:10:094] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:10:154] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [ON]
[12:50:10:154] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 6
[12:50:10:154] [Thread: 3069995952] [Chan 14] - timer id 6 found,
cancelling it now
[12:50:10:154] [Thread: 3069995952] [Chan 14] - Getting ANI digit 0
[12:50:10:154] [Thread: 3069995952] [Chan 14] - ANI so far: 1130,
expected length: 20
[12:50:10:154] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:10:154] [Thread: 3069995952] [Chan 14] - scheduled timer id 7
(mf_back_cycle)
[12:50:10:234] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [OFF]
[12:50:10:234] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:10:294] [Thread: 3069995952] [Chan 14] - MF Rx << 1 [ON]
[12:50:10:294] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 7
[12:50:10:294] [Thread: 3069995952] [Chan 14] - timer id 7 found,
cancelling it now
[12:50:10:294] [Thread: 3069995952] [Chan 14] - Getting ANI digit 1
[12:50:10:294] [Thread: 3069995952] [Chan 14] - ANI so far: 11301,
expected length: 20
[12:50:10:294] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:10:294] [Thread: 3069995952] [Chan 14] - scheduled timer id 8
(mf_back_cycle)
[12:50:10:374] [Thread: 3069995952] [Chan 14] - MF Rx << 1 [OFF]
[12:50:10:374] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:10:454] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [ON]
[12:50:10:454] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 8
[12:50:10:454] [Thread: 3069995952] [Chan 14] - timer id 8 found,
cancelling it now
[12:50:10:454] [Thread: 3069995952] [Chan 14] - Getting ANI digit 0
[12:50:10:454] [Thread: 3069995952] [Chan 14] - ANI so far: 113010,
expected length: 20
[12:50:10:454] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:10:454] [Thread: 3069995952] [Chan 14] - scheduled timer id 9
(mf_back_cycle)
[12:50:10:514] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [OFF]
[12:50:10:514] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:10:594] [Thread: 3069995952] [Chan 14] - MF Rx << 3 [ON]
[12:50:10:594] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 9
[12:50:10:594] [Thread: 3069995952] [Chan 14] - timer id 9 found,
cancelling it now
[12:50:10:594] [Thread: 3069995952] [Chan 14] - Getting ANI digit X -
("modified for security")
[12:50:10:594] [Thread: 3069995952] [Chan 14] - ANI so far: 113010X,
expected length: 20
[12:50:10:594] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:10:594] [Thread: 3069995952] [Chan 14] - scheduled timer id 10
(mf_back_cycle)
[12:50:10:674] [Thread: 3069995952] [Chan 14] - MF Rx << 3 [OFF]
[12:50:10:674] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:10:734] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [ON]
[12:50:10:734] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 10
[12:50:10:734] [Thread: 3069995952] [Chan 14] - timer id 10 found,
cancelling it now
[12:50:10:734] [Thread: 3069995952] [Chan 14] - Getting ANI digit X -
("modified for security")
[12:50:10:734] [Thread: 3069995952] [Chan 14] - ANI so far: 113010XX,
expected length: 20
[12:50:10:734] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:10:734] [Thread: 3069995952] [Chan 14] - scheduled timer id 11
(mf_back_cycle)
[12:50:10:794] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [OFF]
[12:50:10:794] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:10:874] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [ON]
[12:50:10:874] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 11
[12:50:10:874] [Thread: 3069995952] [Chan 14] - timer id 11 found,
cancelling it now
[12:50:10:874] [Thread: 3069995952] [Chan 14] - Getting ANI digit 0
[12:50:10:874] [Thread: 3069995952] [Chan 14] - ANI so far: 113010XX0,
expected length: 20
[12:50:10:874] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:10:874] [Thread: 3069995952] [Chan 14] - scheduled timer id 12
(mf_back_cycle)
[12:50:10:954] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [OFF]
[12:50:10:954] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:11:014] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [ON]
[12:50:11:014] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 12
[12:50:11:014] [Thread: 3069995952] [Chan 14] - timer id 12 found,
cancelling it now
[12:50:11:014] [Thread: 3069995952] [Chan 14] - Getting ANI digit 0
[12:50:11:014] [Thread: 3069995952] [Chan 14] - ANI so far: 113010XX00,
expected length: 20
[12:50:11:014] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [ON]
[12:50:11:014] [Thread: 3069995952] [Chan 14] - scheduled timer id 13
(mf_back_cycle)
[12:50:11:074] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [OFF]
[12:50:11:074] [Thread: 3069995952] [Chan 14] - MF Tx >> 5 [OFF]
[12:50:11:134] [Thread: 3069995952] [Chan 14] - MF Rx << F [ON]
[12:50:11:134] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 13
[12:50:11:134] [Thread: 3069995952] [Chan 14] - timer id 13 found,
cancelling it now
[12:50:11:134] [Thread: 3069995952] [Chan 14] - Got end of ANI
[12:50:11:134] [Thread: 3069995952] [Chan 14] - Requesting next DNIS
with signal 0x31.
[12:50:11:134] [Thread: 3069995952] [Chan 14] - MF Tx >> 1 [ON]
[12:50:11:134] [Thread: 3069995952] [Chan 14] - scheduled timer id 14
(mf_back_cycle)
[12:50:11:214] [Thread: 3069995952] [Chan 14] - MF Rx << F [OFF]
[12:50:11:214] [Thread: 3069995952] [Chan 14] - MF Tx >> 1 [OFF]
[12:50:11:274] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [ON]
[12:50:11:274] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 14
[12:50:11:274] [Thread: 3069995952] [Chan 14] - timer id 14 found,
cancelling it now
[12:50:11:274] [Thread: 3069995952] [Chan 14] - Getting DNIS digit 0
[12:50:11:274] [Thread: 3069995952] [Chan 14] - DNIS so far: 70,
expected length: 20
[12:50:11:274] [Thread: 3069995952] [Chan 14] - Requesting next DNIS
with signal 0x31.
[12:50:11:274] [Thread: 3069995952] [Chan 14] - MF Tx >> 1 [ON]
[12:50:11:274] [Thread: 3069995952] [Chan 14] - scheduled timer id 15
(mf_back_cycle)
[12:50:11:334] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [OFF]
[12:50:11:334] [Thread: 3069995952] [Chan 14] - MF Tx >> 1 [OFF]
[12:50:11:394] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [ON]
[12:50:11:394] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 15
[12:50:11:394] [Thread: 3069995952] [Chan 14] - timer id 15 found,
cancelling it now
[12:50:11:394] [Thread: 3069995952] [Chan 14] - Getting DNIS digit 0
[12:50:11:394] [Thread: 3069995952] [Chan 14] - DNIS so far: 700,
expected length: 20
[12:50:11:394] [Thread: 3069995952] [Chan 14] - Requesting next DNIS
with signal 0x31.
[12:50:11:394] [Thread: 3069995952] [Chan 14] - MF Tx >> 1 [ON]
[12:50:11:394] [Thread: 3069995952] [Chan 14] - scheduled timer id 16
(mf_back_cycle)
[12:50:11:474] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [OFF]
[12:50:11:474] [Thread: 3069995952] [Chan 14] - MF Tx >> 1 [OFF]
[12:50:11:554] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [ON]
[12:50:11:554] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 16
[12:50:11:554] [Thread: 3069995952] [Chan 14] - timer id 16 found,
cancelling it now
[12:50:11:554] [Thread: 3069995952] [Chan 14] - Getting DNIS digit 0
[12:50:11:554] [Thread: 3069995952] [Chan 14] - DNIS so far: 7000,
expected length: 20
[12:50:11:554] [Thread: 3069995952] [Chan 14] - User requested us to
stop getting DNIS!
[12:50:11:554] [Thread: 3069995952] [Chan 14] - Requesting change to
Group II with signal 0x33
[12:50:11:554] [Thread: 3069995952] [Chan 14] - MF Tx >> 3 [ON]
[12:50:11:554] [Thread: 3069995952] [Chan 14] - scheduled timer id 17
(mf_back_cycle)
[12:50:11:634] [Thread: 3069995952] [Chan 14] - MF Rx << 0 [OFF]
[12:50:11:634] [Thread: 3069995952] [Chan 14] - MF Tx >> 3 [OFF]
[12:50:11:694] [Thread: 3069995952] [Chan 14] - MF Rx << 1 [ON]
[12:50:11:694] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 17
[12:50:11:694] [Thread: 3069995952] [Chan 14] - timer id 17 found,
cancelling it now
[12:50:11:694] [Thread: 3069995952] [Chan 14] - MF Tx >> 1 [ON]
[12:50:11:694] [Thread: 3069995952] [Chan 14] - scheduled timer id 18
(mf_back_cycle)
[12:50:11:774] [Thread: 3069995952] [Chan 14] - MF Rx << 1 [OFF]
[12:50:11:774] [Thread: 3069995952] [Chan 14] - MF Tx >> 1 [OFF]
[12:50:11:774] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 18
[12:50:11:774] [Thread: 3069995952] [Chan 14] - timer id 18 found,
cancelling it now
[12:50:11:774] [Thread: 3069995952] [Chan 14] - scheduled timer id 19
(r2_answer_delay)
[12:50:11:934] [Thread: 3069995952] [Chan 14] - Attempting to cancel
timer timer 19
[12:50:11:934] [Thread: 3069995952] [Chan 14] - timer id 19 found,
cancelling it now
[12:50:11:934] [Thread: 3069995952] [Chan 14] - calling timer 19
(r2_answer_delay) callback
[12:50:17:015] [Thread: 3067411376] [Chan 14] - CAS Tx >> [ANSWER] 0x04
[12:50:17:015] [Thread: 3067411376] [Chan 14] - CAS Raw Tx >> 0x05
[12:50:17:520] [Thread: 3067411376] [Chan 14] - Bits changed from 0x00
to 0x04
[12:50:17:520] [Thread: 3067411376] [Chan 14] - CAS Rx << [0x04] 0x04
[12:50:17:520] [Thread: 3067411376] [Chan 14] - Protocol error. Reason =
Invalid CAS, R2 State = Answer Transmitted, MF state = MF Engine Off, MF
Group = Backward Group B, CAS = 0x04
DNIS = 7000, ANI = 113010XX00, MF = 0x20
[12:50:17:520] [Thread: 3067411376] [Chan 14] - Attempting to cancel
timer timer 0
[12:50:17:520] [Thread: 3067411376] [Chan 14] - Cannot cancel timer 0

***********************************************
Rubens,

Use this branch of openr2.

http://openr2.googlecode.com/svn/branches/release-1

I just commited some code to handle metering pulses even when you are
the backward side of the call. Remove your current openr2 installation
and then install it from that branch and recompile Asterisk.

Try again and please, regardless of whether or not the fix works, post
a complete call dump (mfcr2_call_files=yes).

Moy