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

Sat Feb 16 14:36:57 CST 2013

On Fri, Feb 15, 2013 at 08:30:04PM -0600, Richard Mudgett wrote:
>> I thought of posting my question in this mailing list (as opposed to
>> asterisk-users) because I think it is more technical and related to
>> Asterisk's
>> inner workings than a typical user question. I apologize in advance
>> if it is
>> misplaced.
>> 
>> I use Asterisk (1.8) in scenarios which involve SIP/TDM (E1 PRI)
>> interworking,
>
>Since you did not specify which version of 1.8, I hope you are not
>using v1.8.7.  The ./configure script in that version does not setup
>Asterisk to use libpri correctly.

I am observing the problem on a system with
 - Asterisk 1.8.19.1
 - DAHDI 2.6.1
 - libpri 1.4.14 (also tried with 1.4.13)

>> and recently I stumbled on an interesting fact which is causing some
>> inconvenience.
>> While placing calls from SIP on DAHDI, I noticed that Asterisk
>> apparently sends RTP right after receiving a CALL PROCEEDING Q.931
>> message,
>> even if this does not include any progress indication suggesting that
>> there may
>> be inband progress information. All the RTP packets are sent with the
>> marker
>> set, up until Asterisk receives some relevant progress information
>> (PROGRESS/ALERTING with progress indication 1 or 8).
>> 
>> I seem to understand that this behaviour is known, judging by the
>> "prematuremedia" option in sip.conf, but as the documentation of this
>> option
>> states, what is currently possible (setting the option to "no") is to
>> put the
>> call "in progress" and anticipate the SIP 183 response, not
>> preventing Asterisk
>> to send media before some "more proper" progress indication. This is
>> however
>> not a feasible solution, because in my use-case CALL PROCEEDING gets
>> signalled
>> almost immediately, and progress is carried by a "pure" ALERTING
>> without inband
>> indication (and indeed, without any inband progress information) and
>> sending
>> SIP 183 seems to make all the devices I have tested playback the
>> silence/"garbage" they receive with the RTP "ignoring" the SIP 180
>> generated by
>> the ALERTING.
>> 
>> If you think that this may not be considered a bug, may I ask you a
>> little help
>> on how this may be obtained by a patch? My study of Asterisk's source
>> code is
>> sadly still in very early stages, and I am having some trouble
>> tracing back the
>> point in which "the media path gets opened". I confess that my
>> current
>> understanding does not even include (pardon any miswording here)
>> notions about
>> how and when voice frames start being read from TDM, and if this is
>> preventable
>> at all. If you feel the issue or my case in general is beyond hope,
>> or would
>> like to point out some documentation to help me, I offer you my
>> earnest thanks
>> in advance. Also, I apologize for any incorrectness in the technical
>> matters
>> exposed, which I tried to leave "vague" (and thus prone to remarks or
>> doubts)
>> for the sake of brevity, hoping you can follow the main lines in my
>> reasoning.
>
>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
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.

Thank you in advance for your help and the time spent on this.

Gianluca
-------------- next part --------------
[Feb 16 16:07:17] PRI Span: 1 -- Making new call for cref 32769
[Feb 16 16:07:17] PRI Span: 1 Adding facility ie contents to send in SETUP message:
[Feb 16 16:07:17] PRI Span: 1 ASN.1 dump
[Feb 16 16:07:17] PRI Span: 1   Context Specific/C [1 0x01] <A1> Len:31 <1F>
[Feb 16 16:07:17] PRI Span: 1     Integer(2 0x02) <02> Len:1 <01>
[Feb 16 16:07:17] PRI Span: 1       <01> - "~"
[Feb 16 16:07:17] PRI Span: 1     Integer(2 0x02) <02> Len:1 <01>
[Feb 16 16:07:17] PRI Span: 1       <0F> - "~"
[Feb 16 16:07:17] PRI Span: 1     Sequence/C(48 0x30) <30> Len:23 <17>
[Feb 16 16:07:17] PRI Span: 1       Integer(2 0x02) <02> Len:1 <01>
[Feb 16 16:07:17] PRI Span: 1         <01> - "~"
[Feb 16 16:07:17] PRI Span: 1       Enumerated(10 0x0A) <0A> Len:1 <01>
[Feb 16 16:07:17] PRI Span: 1         <01> - "~"
[Feb 16 16:07:17] PRI Span: 1       Context Specific/C [1 0x01] <A1> Len:15 <0F>
[Feb 16 16:07:17] PRI Span: 1         Context Specific/C [0 0x00] <A0> Len:13 <0D>
[Feb 16 16:07:17] PRI Span: 1           Context Specific/C [1 0x01] <A1> Len:11 <0B>
[Feb 16 16:07:17] PRI Span: 1             Enumerated(10 0x0A) <0A> Len:1 <01>
[Feb 16 16:07:17] PRI Span: 1               <01> - "~"
[Feb 16 16:07:17] PRI Span: 1             Numeric String(18 0x12) <12> Len:6 <06>
[Feb 16 16:07:17] PRI Span: 1               <36 31 35 30 33 30> - "615030"
[Feb 16 16:07:17] PRI Span: 1 ASN.1 end
[Feb 16 16:07:17] PRI Span: 1 INVOKE Component Context Specific/C [1 0x01]
[Feb 16 16:07:17] PRI Span: 1   invokeId Integer(2 0x02) = 1 0x0001
[Feb 16 16:07:17] PRI Span: 1   operationValue Integer(2 0x02) = 15 0x000F
[Feb 16 16:07:17] PRI Span: 1   operationValue = ROSE_ETSI_DivertingLegInformation2
[Feb 16 16:07:17] PRI Span: 1   DivertingLegInformation2 Sequence/C(48 0x30)
[Feb 16 16:07:17] PRI Span: 1   diversionCounter Integer(2 0x02) = 1 0x0001
[Feb 16 16:07:17] PRI Span: 1   diversionReason Enumerated(10 0x0A) = 1 0x0001
[Feb 16 16:07:17] PRI Span: 1   Explicit Context Specific/C [1 0x01]
[Feb 16 16:07:17] PRI Span: 1   divertingNr PresentedNumberUnscreened
[Feb 16 16:07:17] PRI Span: 1   Explicit Context Specific/C [0 0x00]
[Feb 16 16:07:17] PRI Span: 1   presentationAllowedNumber PartyNumber
[Feb 16 16:07:17] PRI Span: 1   publicPartyNumber Context Specific/C [1 0x01]
[Feb 16 16:07:17] PRI Span: 1   typeOfNumber Enumerated(10 0x0A) = 1 0x0001
[Feb 16 16:07:17] PRI Span: 1   numberDigits Numeric String(18 0x12) = "615030"
[Feb 16 16:07:17] PRI Span: 1 
[Feb 16 16:07:17] PRI Span: 1 > DL-DATA request
[Feb 16 16:07:17] PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=83
[Feb 16 16:07:17] PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent from originator)
[Feb 16 16:07:17] PRI Span: 1 > Message Type: SETUP (5)
[Feb 16 16:07:17] PRI Span: 1 TEI=0 Transmitting N(S)=7, window is open V(A)=7 K=7
[Feb 16 16:07:17] PRI Span: 1 
[Feb 16 16:07:17] PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=83
[Feb 16 16:07:17] PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent from originator)
[Feb 16 16:07:17] PRI Span: 1 > Message Type: SETUP (5)
[Feb 16 16:07:17] PRI Span: 1 > [04 03 80 90 a3]
[Feb 16 16:07:17] PRI Span: 1 > Bearer Capability (len= 5) [ Ext: 1  Coding-Std: 0  Info transfer capability: Speech (0)
[Feb 16 16:07:17] PRI Span: 1 >                              Ext: 1  Trans mode/rate: 64kbps, circuit-mode (16)
[Feb 16 16:07:17] PRI Span: 1 >                                User information layer 1: A-Law (35)
[Feb 16 16:07:17] PRI Span: 1 > [18 03 a1 83 81]
[Feb 16 16:07:17] PRI Span: 1 > Channel ID (len= 5) [ Ext: 1  IntID: Implicit  Other(PRI)  Spare: 0  Preferred  Dchan: 0
[Feb 16 16:07:17] PRI Span: 1 >                       ChanSel: As indicated in following octets
[Feb 16 16:07:17] PRI Span: 1 >                       Ext: 1  Coding: 0  Number Specified  Channel Type: 3
[Feb 16 16:07:17] PRI Span: 1 >                       Ext: 1  Channel: 1 Type: CPE]
[Feb 16 16:07:17] PRI Span: 1 > [1c 22 91 a1 1f 02 01 01 02 01 0f 30 17 02 01 01 0a 01 01 a1 0f a0 0d a1 0b 0a 01 01 12 06 36 31 35 30 33 30]
[Feb 16 16:07:17] PRI Span: 1 > Facility (len=36, codeset=0) [ 0x91, '?', 0x1F, 0x02, 0x01, 0x01, 0x02, 0x01, 0x0F, '0', 0x17, 0x02, 0x01, 0x01, 0x0A, 0x01, 0x01, '?', 0x0F, '?', 0x0D, '?', 0x0B, 0x0A, 0x01, 0x01, 0x12, 0x06, '615030' ]
[Feb 16 16:07:17] PRI Span: 1 > [6c 0e 11 81 3x 3x 3x 3x 3x 3x 3x 3x 3x 3x 3x 3x]
[Feb 16 16:07:17] PRI Span: 1 > Calling Party Number (len=16) [ Ext: 0  TON: International Number (1)  NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
[Feb 16 16:07:17] PRI Span: 1 >                                 Presentation: Presentation allowed, User-provided, verified and passed (1)  'xxxxxxxxxxxx' ]
[Feb 16 16:07:17] PRI Span: 1 > [70 0d 91 3x 3x 3x 3x 3x 3x 3x 3x 3x 3x 3x 3x]
[Feb 16 16:07:17] PRI Span: 1 > Called Party Number (len=15) [ Ext: 1  TON: International Number (1)  NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)  'xxxxxxxxxxxx' ]
[Feb 16 16:07:17] PRI Span: 1 > [a1]
[Feb 16 16:07:17] PRI Span: 1 > Sending Complete (len= 1)
[Feb 16 16:07:17] PRI Span: 1 q931.c:6334 q931_setup: Call 32769 enters state 1 (Call Initiated).  Hold state: Idle
[Feb 16 16:07:17] PRI Span: 1 
[Feb 16 16:07:17] PRI Span: 1 < Protocol Discriminator: Q.931 (8)  len=10
[Feb 16 16:07:17] PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent to originator)
[Feb 16 16:07:17] PRI Span: 1 < Message Type: CALL PROCEEDING (2)
[Feb 16 16:07:17] PRI Span: 1 < [18 03 a9 83 81]
[Feb 16 16:07:17] PRI Span: 1 < Channel ID (len= 5) [ Ext: 1  IntID: Implicit  Other(PRI)  Spare: 0  Exclusive  Dchan: 0
[Feb 16 16:07:17] PRI Span: 1 <                       ChanSel: As indicated in following octets
[Feb 16 16:07:17] PRI Span: 1 <                       Ext: 1  Coding: 0  Number Specified  Channel Type: 3
[Feb 16 16:07:17] PRI Span: 1 <                       Ext: 1  Channel: 1 Type: CPE]
[Feb 16 16:07:17] PRI Span: 1 Received message for call 0xc2aae0 on link 0x7f28fc5071f0 TEI/SAPI 0/0
[Feb 16 16:07:17] PRI Span: 1 -- Processing IE 24 (cs0, Channel ID)
[Feb 16 16:07:17] PRI Span: 1 q931.c:8831 post_handle_q931_message: Call 32769 enters state 3 (Outgoing Call Proceeding).  Hold state: Idle
[Feb 16 16:07:17] Span 1: Processing event PRI_EVENT_PROCEEDING
[Feb 16 16:07:23] PRI Span: 1 
[Feb 16 16:07:23] PRI Span: 1 < Protocol Discriminator: Q.931 (8)  len=9
[Feb 16 16:07:23] PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent to originator)
[Feb 16 16:07:23] PRI Span: 1 < Message Type: PROGRESS (3)
[Feb 16 16:07:23] PRI Span: 1 < [1e 02 84 88]
[Feb 16 16:07:23] PRI Span: 1 < Progress Indicator (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  0: 0  Location: Public network serving the remote user (4)
[Feb 16 16:07:23] PRI Span: 1 <                               Ext: 1  Progress Description: Inband information or appropriate pattern now available. (8) ]
[Feb 16 16:07:23] PRI Span: 1 Received message for call 0xc2aae0 on link 0x7f28fc5071f0 TEI/SAPI 0/0
[Feb 16 16:07:23] PRI Span: 1 -- Processing IE 30 (cs0, Progress Indicator)
[Feb 16 16:07:23] Span 1: Processing event PRI_EVENT_PROGRESS
[Feb 16 16:07:28] PRI Span: 1 
[Feb 16 16:07:28] PRI Span: 1 < Protocol Discriminator: Q.931 (8)  len=9
[Feb 16 16:07:28] PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent to originator)
[Feb 16 16:07:28] PRI Span: 1 < Message Type: ALERTING (1)
[Feb 16 16:07:28] PRI Span: 1 < [1e 02 84 88]
[Feb 16 16:07:28] PRI Span: 1 < Progress Indicator (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  0: 0  Location: Public network serving the remote user (4)
[Feb 16 16:07:28] PRI Span: 1 <                               Ext: 1  Progress Description: Inband information or appropriate pattern now available. (8) ]
[Feb 16 16:07:28] PRI Span: 1 Received message for call 0xc2aae0 on link 0x7f28fc5071f0 TEI/SAPI 0/0
[Feb 16 16:07:28] PRI Span: 1 -- Processing IE 30 (cs0, Progress Indicator)
[Feb 16 16:07:28] PRI Span: 1 q931.c:8684 post_handle_q931_message: Call 32769 enters state 4 (Call Delivered).  Hold state: Idle
[Feb 16 16:07:28] Span 1: Processing event PRI_EVENT_RINGING
[Feb 16 16:07:36] PRI Span: 1 q931.c:7135 q931_hangup: Hangup other cref:32769
[Feb 16 16:07:36] PRI Span: 1 q931.c:6892 __q931_hangup: ourstate Call Delivered, peerstate Call Received, hold-state Idle
[Feb 16 16:07:36] PRI Span: 1 q931.c:6081 q931_disconnect: Call 32769 enters state 11 (Disconnect Request).  Hold state: Idle
[Feb 16 16:07:36] PRI Span: 1 
[Feb 16 16:07:36] PRI Span: 1 > DL-DATA request
[Feb 16 16:07:36] PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=9
[Feb 16 16:07:36] PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent from originator)
[Feb 16 16:07:36] PRI Span: 1 > Message Type: DISCONNECT (69)
[Feb 16 16:07:36] PRI Span: 1 TEI=0 Transmitting N(S)=8, window is open V(A)=8 K=7
[Feb 16 16:07:36] PRI Span: 1 
[Feb 16 16:07:36] PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=9
[Feb 16 16:07:36] PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent from originator)
[Feb 16 16:07:36] PRI Span: 1 > Message Type: DISCONNECT (69)
[Feb 16 16:07:36] PRI Span: 1 > [08 02 81 90]
[Feb 16 16:07:36] PRI Span: 1 > Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  Spare: 0  Location: Private network serving the local user (1)
[Feb 16 16:07:36] PRI Span: 1 >                  Ext: 1  Cause: Normal Clearing (16), class = Normal Event (1) ]
[Feb 16 16:07:36] PRI Span: 1 
[Feb 16 16:07:36] PRI Span: 1 < Protocol Discriminator: Q.931 (8)  len=5
[Feb 16 16:07:36] PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent to originator)
[Feb 16 16:07:36] PRI Span: 1 < Message Type: RELEASE (77)
[Feb 16 16:07:36] PRI Span: 1 Received message for call 0xc2aae0 on link 0x7f28fc5071f0 TEI/SAPI 0/0
[Feb 16 16:07:36] PRI Span: 1 q931.c:8997 post_handle_q931_message: Call 32769 enters state 0 (Null).  Hold state: Idle
[Feb 16 16:07:36] Span 1: Processing event PRI_EVENT_HANGUP
[Feb 16 16:07:36] PRI Span: 1 q931.c:7135 q931_hangup: Hangup other cref:32769
[Feb 16 16:07:36] PRI Span: 1 q931.c:6892 __q931_hangup: ourstate Null, peerstate Release Request, hold-state Idle
[Feb 16 16:07:36] PRI Span: 1 
[Feb 16 16:07:36] PRI Span: 1 > DL-DATA request
[Feb 16 16:07:36] PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=9
[Feb 16 16:07:36] PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent from originator)
[Feb 16 16:07:36] PRI Span: 1 > Message Type: RELEASE COMPLETE (90)
[Feb 16 16:07:36] PRI Span: 1 TEI=0 Transmitting N(S)=9, window is open V(A)=9 K=7
[Feb 16 16:07:36] PRI Span: 1 
[Feb 16 16:07:36] PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=9
[Feb 16 16:07:36] PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 1/0x1) (Sent from originator)
[Feb 16 16:07:36] PRI Span: 1 > Message Type: RELEASE COMPLETE (90)
[Feb 16 16:07:36] PRI Span: 1 > [08 02 81 90]
[Feb 16 16:07:36] PRI Span: 1 > Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  Spare: 0  Location: Private network serving the local user (1)
[Feb 16 16:07:36] PRI Span: 1 >                  Ext: 1  Cause: Normal Clearing (16), class = Normal Event (1) ]
[Feb 16 16:07:36] PRI Span: 1 q931.c:7135 q931_hangup: Hangup other cref:32769
[Feb 16 16:07:36] PRI Span: 1 q931.c:6892 __q931_hangup: ourstate Null, peerstate Null, hold-state Idle
[Feb 16 16:07:36] PRI Span: 1 Destroying call 0xc2aae0, ourstate Null, peerstate Null, hold-state Idle