[asterisk-dev] SIP/TDM interworking, and RTP on CALL PROCEEDING

[Gianluca Merlo]

On Mon, Feb 18, 2013 at 11:13:38AM -0600, Richard Mudgett wrote:
>> >> >I would like to see a "pri set debug on span x" trace of the
>> >> >call.
>> >>
>> >> I am attaching what I hope is enough. The debug is actually
>> >> "intense", and I
>> >
>> >That trace is not intense.  It is decoding the Q.931 (layer 3)
>> >messages.
>> >The intense trace is *only* needed when debugging Q.921 (layer 2)
>> >problems.
>> >Otherwise, the intense trace just fills the log with unnecessary
>> >noise.
>> 
>> I'm sorry. I did not intend to do something not in your requests. It
>> was not my
>> intention to make the log less readable, or make you spend more time
>> in reading
>> unnecessary details.
>
>You supplied exactly what I asked.  I was just commenting on your
>description of the trace as "intense".
>
>> >> overwrote references to actual numbers. In this call, which is
>> >> made
>> >> to a test
>> >> destination, CALL PROCEEDING and further progress informations are
>> >> purposely
>> >> separated by 5 seconds of wait. The RTP flow seems to start after
>> >> the
>> >> PRI_EVENT_PROCEEDING gets indicated on the SIP channel, and the
>> >> corresponding
>> >> 100 Trying gets sent.
>> >
>> >I think you may be confusing things.  The PRI_EVENT_PROCEEDING is
>> >associated with the DAHDI channel not the SIP channel.  Messages
>> >from different threads can come out delayed relative to when things
>> >actually happen between threads.
>> 
>> I may, indeed, be confusing something. As I said I surely do not
>> match your
>> expertise in the field, but I think that I was possibly misleading in
>> my
>> explanation. What I meant to say, (I hope) more properly is that what
>> I see
>> is:
>> 
>>  - CALL PROCEEDING coming on the DAHDI channel
>>  - 100 Trying on the SIP channel
>>  - RTP being sent immediately after this, and before any other
>> progress indication
>>    (being it PROGRESS, ALERTING, with relevant progress indication 1
>>    or 8)
>> 
>> >The trace shows Asterisk receiving
>> >PROCEEDING (with no progress indication ie)
>> >wait 5 seconds
>> >PROGRESS (with progress indication ie)
>> >wait 5 seconds
>> >ALERTING (with progress indication ie)
>> >
>> >The PROCEEDING message will cause the SIP channel to send a
>> >"100 Trying" message.  The SIP message should not have a SDP body.
>> >The PROCEEDING message does not have a progress indication ie and
>> >will not open the media path from the DAHDI channel.
>> >
>> >The PROGRESS message will cause the SIP channel to send a
>> >"183 Session Progress" message.  There should also be a SDP
>> >body to open the RTP media path to the calling phone.  The
>> >PROGRESS message *does* have a progress indication ie and *will*
>> >open the media path from the DAHDI channel.
>> >
>> >The ALERTING message may cause the SIP channel to send a
>> >"180 Ringing" if it has not previously send a 183 message.
>> >The ALERTING message also has a progress indication ie that would
>> >open the media path from the DAHDI channel if it were not already
>> >opened by the previous PROGRESS message.
>> >
>> >This behavior would be expected from the messages in the trace.
>> 
>> I can confirm that your description of what seen on the trace is
>> flawless,
>> however, nonetheless it seems that the RTP flow starts right after
>> the CALL
>> PROCEEDING, and before receiving other progress information. As I
>> said, this is what
>> I was not expecting. I thought (as you do, I think), that a CALL
>> PROCEEDING without
>> any progress indication 1 or 8 would lead to sending only a 100
>> Trying
>> on the SIP
>> channel, without leading to any media being sent.
>
>Since your trace has a PROGRESS message that *will* open the media
>path before the ALERTING message comes in, here is a test change
>that will disable posting the PROGRESS control frame to the SIP
>channel:
>
>Index: channels/sig_pri.c
>===================================================================
>--- channels/sig_pri.c  (revision 381627)
>+++ channels/sig_pri.c  (working copy)
>@@ -5617,6 +5617,7 @@
>                                        }
>                                }
>
>+#if 0  /* For testing purposes ONLY. */
>                                if (!pri->pvts[chanpos]->progress
>                                        && !pri->pvts[chanpos]->no_b_channel
> #ifdef PRI_PROGRESS_MASK
>@@ -5636,6 +5637,7 @@
>                                        sig_pri_set_dialing(pri->pvts[chanpos], 0);
>                                        sig_pri_open_media(pri->pvts[chanpos]);
>                                }
>+#endif /* For testing purposes ONLY. */
>                                sig_pri_unlock_private(pri->pvts[chanpos]);
>                                break;
>                        case PRI_EVENT_PROCEEDING:
>
>
>Please try this to see if this suppresses your early RTP stream.

Hello Richard,

I am sorry for the delay in providing a feedback, which is due to the tests I
have made on this matter.

Unfortunately, your suggestion does affect the behaviour of Asterisk upon
receiving PROGRESS, and in the test scenario we are discussing this only leads
to having the SIP 183 delayed until an ALERTING with progress indicator 8 comes
in. The RTP sent after call proceeding is not affected by this modification.

As I said, not to bother you too much, and following my initial research path,
I went back with the help of a friend and colleague to verify the part of the
code you pointed out in your patch, and more specifically the handling of
PRI_EVENT_PROCEEDING immediately after the part you suggested to patch.
After some trial and error, I seem to trace the origin of the behaviour to the
call to sig_pri_set_dialing(), which is performed right before
sig_pri_unlock_private() and breaking out of the case statement
(channels/sig_pri.c:5671 in 1.8.19.1). It seems that the "dialing" member of
the DAHDI private struct (which is set to 0 by this call) affects subsequent
calls to dahdi_read(), leading it to return voice frames when it (imho) should
not, which in turn get sent over to the SIP channel.

Apart from this description, I hope that you can answer some questions
regarding these parameters and calls:

 - What is the expected role of the "dialing" dahdi private struct member? Are
   my assumptions, by your advice, correct?

 - I see that apparently calls to sig_pri_set_dialing() like the one I am
   supposing as the origin of my issue generally come when you call
   sig_pri_open_media() and when there is a progress indication which suggests
   that inband information is available on the channel. You explicitly comment
   many parts like these in the code with the comment "Bring voice path up". Is
   it correct that the handling of PRI_EVENT_PROCEEDING is seemingly the only
   exception, having a call to sig_pri_set_dialing() irregardless of the
   presence of a progress indication in Q.931 signalling, and of a call to
   sig_pri_open_media()?

 - This is partly related to my previous question, but is it correct that all
   this is related to the issue in:

   https://issues.asterisk.org/jira/browse/ASTERISK-17834

   and that it seems that the call to sig_pri_set_dialing() was moved to be
   made even without a proper progress indication (and a call to
   sig_pri_open_media()) to accomodate the scenario in this issue?

I thank you in advance for your help in reviewing my ponderings.

Best regards

Gianluca