[asterisk-r2] Inbound R2 and Agi

ServTelar servtelar at gmail.com
Thu Jun 14 21:19:19 CDT 2012 

> 
> Would you mind sharing the solution?
> 
> I could not understand the problem completely, but sounded like you wanted to use mfcr2_accept_on_offer=no 
> 

Moy

I installed a Ast 10.5, OpenR2 1.3.2. All things are working properly (just a little thing I mentioned in the previous email).

Using mfcr2_accept_on_offer leads me to another observation. Speaking on plain ITU-T variant register signals, I saw that chan_dahdi only send a B6 when the call is answered. This behavior is a bit strange, because the B6 should be sent as soon as the far end indicates Ringing state.
Added the fact off avoid to have a register taken for more time, this was used for long time to know what's going on with the call, and automatic equipments can launch different kind of processes depending on the call status. That's why in general terms, this register signal is sent ASAP.

For this case the test bed is:

Ameritec AM8e 		---> 		AST 10.5/OpenR2 1.3.2 		--->		Polycom IP 330 SIP


The AM8e is a good old fashion Protocol Analyzer/Emulator. When the call is sent to the Polycom, and the chan_dahdi has indication of AST_CONTROL_RINGING nothing happens.

This is the output of Ast10.5:

[2012-06-14 22:44:25.034] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Bits changed from 0x08 to 0x00
[2012-06-14 22:44:25.034] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - CAS Rx << [SEIZE] 0x00
[2012-06-14 22:44:25.034] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Call started at Thu Jun 14 22:44:25 2012 on chan 1 [openr2 version 1.3.2, revision exported]
[2012-06-14 22:44:25.034] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Initialized R2 MF detector
[2012-06-14 22:44:25.034] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - CAS Tx >> [SEIZE ACK] 0x0C
[2012-06-14 22:44:25.034] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - CAS Raw Tx >> 0x0D
New MFC/R2 call detected on chan 1.
[2012-06-14 22:44:25.083] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 5 [ON]
[2012-06-14 22:44:25.083] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Getting DNIS digit 5
[2012-06-14 22:44:25.083] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - DNIS so far: 5, expected length: 25
[2012-06-14 22:44:25.083] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [ON]
[2012-06-14 22:44:25.163] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 5 [OFF]
[2012-06-14 22:44:25.163] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [OFF]
[2012-06-14 22:44:25.223] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 1 [ON]
[2012-06-14 22:44:25.223] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [ON]
[2012-06-14 22:44:25.323] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 1 [OFF]
[2012-06-14 22:44:25.323] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [OFF]
[2012-06-14 22:44:25.363] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 4 [ON]
[2012-06-14 22:44:25.363] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Getting ANI digit 4
[2012-06-14 22:44:25.363] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - ANI so far: 4, expected length: 25
[2012-06-14 22:44:25.363] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [ON]
[2012-06-14 22:44:25.443] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 4 [OFF]
[2012-06-14 22:44:25.443] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [OFF]
[2012-06-14 22:44:25.483] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 7 [ON]
--- SNIP ---
[2012-06-14 22:44:27.143] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Getting DNIS digit 3
[2012-06-14 22:44:27.143] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - DNIS so far: 5269213, expected length: 25
[2012-06-14 22:44:27.143] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Requesting next DNIS with signal 0x31.
[2012-06-14 22:44:27.143] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 1 [ON]
[2012-06-14 22:44:27.223] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 3 [OFF]
[2012-06-14 22:44:27.223] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 1 [OFF]
[2012-06-14 22:44:27.263] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 7 [ON]
[2012-06-14 22:44:27.263] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Getting DNIS digit 7
[2012-06-14 22:44:27.263] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - DNIS so far: 52692137, expected length: 25
[2012-06-14 22:44:27.263] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Requesting next DNIS with signal 0x31.
[2012-06-14 22:44:27.263] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 1 [ON]
[2012-06-14 22:44:27.343] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 7 [OFF]
[2012-06-14 22:44:27.343] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 1 [OFF]
[2012-06-14 22:44:32.262] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - calling timer 19 (mf_back_cycle) callback
[2012-06-14 22:44:32.263] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF cycle timed out, no more DNIS
[2012-06-14 22:44:32.263] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Requesting change to Group II with signal 0x33
[2012-06-14 22:44:32.263] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 3 [ON]
[2012-06-14 22:44:32.422] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - calling timer 20 (mf_back_resume_cycle) callback
[2012-06-14 22:44:32.423] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 3 [OFF]
[2012-06-14 22:44:32.462] DEBUG[27651]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 1 [ON]
MFC/R2 call offered on chan 1. ANI = (restricted), DNIS = 52692137, Category = National Subscriber
[2012-06-14 22:44:32.463] DEBUG[27651]: dsp.c:463 ast_tone_detect_init: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21

[2012-06-14 22:44:32.463] DEBUG[27757]: pbx.c:4371 pbx_extension_helper: Launching 'Dial'
    -- Executing [52692137 at common:1] Dial("DAHDI/1-1", "SIP/01152692137") in new stack

[2012-06-14 22:44:32.617] DEBUG[19787]: devicestate.c:438 devstate_event: device 'SIP/01152692137' state '1'
    -- SIP/01152692137-0000000d is ringing
[2012-06-14 22:44:32.617] DEBUG[27757]: chan_dahdi.c:9486 dahdi_indicate: Requested indication 3 on channel DAHDI/1-1

As we can see, the indication 3 (AST_CONTROL_RINGING) is ignored.

--- Answering the call, 8 seconds from the ringing ---

[2012-06-14 22:44:40.617] DEBUG[19814]: chan_sip.c:20561 handle_response_invite: SIP response 200 to standard invite
[2012-06-14 22:44:40.618] DEBUG[27757]: chan_dahdi.c:6669 dahdi_answer: Accepting MFC/R2 call with charge before answering on chan 1
[2012-06-14 22:44:40.618] DEBUG[27757]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 6 [ON]
[2012-06-14 22:44:40.618] DEBUG[27757]: chan_dahdi.c:9486 dahdi_indicate: Requested indication -1 on channel DAHDI/1-1
[2012-06-14 22:44:40.618] DEBUG[27757]: chan_dahdi.c:9486 dahdi_indicate: Requested indication 20 on channel DAHDI/1-1
[2012-06-14 22:44:40.702] DEBUG[27757]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 1 [OFF]
[2012-06-14 22:44:40.702] DEBUG[27757]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 6 [OFF]
MFC/R2 call has been accepted on backward channel 1
[2012-06-14 22:44:40.862] DEBUG[27757]: chan_dahdi.c:4059 dahdi_r2_on_call_accepted: Answering MFC/R2 call after accepting it on chan 1
[2012-06-14 22:44:40.862] DEBUG[27757]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - CAS Tx >> [ANSWER] 0x04
[2012-06-14 22:44:40.862] DEBUG[27757]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - CAS Raw Tx >> 0x05


The AST_CONTROL_RINGING is ignored in the dahdi_indicate by this piece of code:

#ifdef HAVE_OPENR2
    if (p->mfcr2 && !p->mfcr2_call_accepted) {
        ast_mutex_unlock(&p->lock);
        /* if this is an R2 call and the call is not yet accepted, we don't want the
           tone indications to mess up with the MF tones */
        return 0;
    }
#endif


Just to test, I commented that part of the code, and I added the following in the AST_CONTROL_RINGING case, just before the break:

#if HAVE_OPENR2
            if (p->mfcr2) {
                ast_log(LOG_ERROR, "The other side started to ring. We send the signal 'subscriber free, charge'\n");
                openr2_chan_accept_call(p->r2chan, OR2_CALL_WITH_CHARGE);
            }
#endif

Now, when AM8e send the call:

[2012-06-14 22:56:00.313] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Bits changed from 0x08 to 0x00
[2012-06-14 22:56:00.313] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - CAS Rx << [SEIZE] 0x00
[2012-06-14 22:56:00.313] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Call started at Thu Jun 14 22:56:00 2012 on chan 1 [openr2 version 1.3.2, revision exported]
[2012-06-14 22:56:00.313] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Initialized R2 MF detector
[2012-06-14 22:56:00.313] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - CAS Tx >> [SEIZE ACK] 0x0C
[2012-06-14 22:56:00.313] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - CAS Raw Tx >> 0x0D
New MFC/R2 call detected on chan 1.
[2012-06-14 22:56:00.365] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 5 [ON]
[2012-06-14 22:56:00.365] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Getting DNIS digit 5
[2012-06-14 22:56:00.365] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - DNIS so far: 5, expected length: 25
[2012-06-14 22:56:00.365] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [ON]
[2012-06-14 22:56:00.445] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 5 [OFF]
[2012-06-14 22:56:00.445] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [OFF]
[2012-06-14 22:56:00.505] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 1 [ON]
[2012-06-14 22:56:00.505] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [ON]
[2012-06-14 22:56:00.585] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 1 [OFF]
[2012-06-14 22:56:00.585] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [OFF]
[2012-06-14 22:56:00.625] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 4 [ON]
[2012-06-14 22:56:00.625] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Getting ANI digit 4
[2012-06-14 22:56:00.625] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - ANI so far: 4, expected length: 25
[2012-06-14 22:56:00.625] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [ON]
[2012-06-14 22:56:00.705] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 4 [OFF]
[2012-06-14 22:56:00.705] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 5 [OFF]
[2012-06-14 22:56:00.745] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 7 [ON]
--- SNIP ---
[2012-06-14 22:56:02.324] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 3 [ON]
[2012-06-14 22:56:02.325] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Getting DNIS digit 3
[2012-06-14 22:56:02.325] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - DNIS so far: 5269213, expected length: 25
[2012-06-14 22:56:02.325] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Requesting next DNIS with signal 0x31.
[2012-06-14 22:56:02.325] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 1 [ON]
[2012-06-14 22:56:02.384] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 3 [OFF]
[2012-06-14 22:56:02.385] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 1 [OFF]
[2012-06-14 22:56:02.424] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 7 [ON]
[2012-06-14 22:56:02.425] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Getting DNIS digit 7
[2012-06-14 22:56:02.425] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - DNIS so far: 52692137, expected length: 25
[2012-06-14 22:56:02.425] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Requesting next DNIS with signal 0x31.
[2012-06-14 22:56:02.425] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 1 [ON]
[2012-06-14 22:56:02.504] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 7 [OFF]
[2012-06-14 22:56:02.505] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 1 [OFF]
[2012-06-14 22:56:07.424] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - calling timer 19 (mf_back_cycle) callback
[2012-06-14 22:56:07.424] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF cycle timed out, no more DNIS
[2012-06-14 22:56:07.424] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - Requesting change to Group II with signal 0x33
[2012-06-14 22:56:07.425] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 3 [ON]
[2012-06-14 22:56:07.584] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - calling timer 20 (mf_back_resume_cycle) callback
[2012-06-14 22:56:07.584] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 3 [OFF]
[2012-06-14 22:56:07.624] DEBUG[28568]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 1 [ON]
MFC/R2 call offered on chan 1. ANI = (restricted), DNIS = 52692137, Category = National Subscriber

[2012-06-14 22:56:07.625] DEBUG[28572]: pbx.c:4371 pbx_extension_helper: Launching 'Dial'
    -- Executing [52692137 at common:1] Dial("DAHDI/1-1", "SIP/01152692137") in new stack

[2012-06-14 22:56:07.783] DEBUG[19814]: chan_sip.c:20561 handle_response_invite: SIP response 180 to standard invite

[2012-06-14 22:56:07.783] DEBUG[28572]: chan_dahdi.c:9486 dahdi_indicate: Requested indication 3 on channel DAHDI/1-1
[2012-06-14 22:56:07.783] ERROR[28572]: chan_dahdi.c:9531 dahdi_indicate: The other side started to ring. We send the signal 'subscriber free, charge'
[2012-06-14 22:56:07.783] DEBUG[28572]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 6 [ON]
[2012-06-14 22:56:07.783] DEBUG[19787]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1
[2012-06-14 22:56:07.783] DEBUG[19787]: devicestate.c:458 do_state_change: Changing state for DAHDI/1 - state 6 (Ringing)
[2012-06-14 22:56:07.783] DEBUG[19787]: devicestate.c:438 devstate_event: device 'DAHDI/1' state '6'
[2012-06-14 22:56:07.783] DEBUG[19821]: app_queue.c:1511 handle_statechange: Device 'DAHDI/1' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
[2012-06-14 22:56:07.864] DEBUG[28572]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Rx << 1 [OFF]
[2012-06-14 22:56:07.864] DEBUG[28572]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - MF Tx >> 6 [OFF]
[2012-06-14 22:56:08.024] DEBUG[28572]: chan_dahdi.c:4176 dahdi_r2_write_log: Chan 1 - calling timer 23 (r2_answer_delay) callback
[2012-06-14 22:56:08.024] DEBUG[28572]: chan_dahdi.c:4966 dahdi_enable_ec: Enabled echo cancellation on channel 1
MFC/R2 call has been accepted on backward channel 1
[2012-06-14 22:56:08.024] DEBUG[28572]: res_rtp_asterisk.c:1323 ast_rtp_write: No remote address on RTP instance '0x9d03338' so dropping frame
[2012-06-14 22:56:08.044] DEBUG[28572]: res_rtp_asterisk.c:1323 ast_rtp_write: No remote address on RTP instance '0x9d03338' so dropping frame
[2012-06-14 22:56:08.064] DEBUG[28572]: res_rtp_asterisk.c:1323 ast_rtp_write: No remote address on RTP instance '0x9d03338' so dropping frame


Obviously, that is not the only thing to change, because Ast start complaint about RTP, but at least the B6 was sent in time.

Is that the code we should modify to fix this particular behavior?


Best regards

Gustavo

More information about the asterisk-r2 mailing list