[asterisk-users] PRI timing settings

Wed Aug 20 12:28:39 CDT 2014

On 08/20/2014 12:04 PM, Andres wrote:
> On 8/20/14, 11:28 AM, Steve Totaro wrote:
>> PRI intense debug should show all you need to fix this.
>>
> Right, the sooner you post this debug here the sooner we can help.  
> Otherwise its just guesswork.
>>
>> On Wed, Aug 20, 2014 at 12:13 PM, Jeff LaCoursiere <jeff at jeff.net 
>> <mailto:jeff at jeff.net>> wrote:
>>
>>
>>     Sadly none of these changes have made any difference. I'll report
>>     the resolution for posterity once we find it.
>>
>>     Thanks,
>>
>>     j
>>
>>
>>

Ok, here is an intense debug trace.  I've replaced the phone numbers to 
protect the innocent.  The smoking gun seems to be this:

Ext: 1  Cause: Destination out of order (27)

Though I have no idea why... calling the same destination from my cell 
phone works fine.  We only send seven digits for local "on-island" calls 
like this, and calls to other carriers work fine with the same format.  
I'm starting to doubt there is anything I can do to fix this... seems 
like an issue between my telco and Sprint?

Cheers,

j

astsouth*CLI> pri intense debug span 1
Enabled debugging on span 1
PRI Span: 1 t203_expire
PRI Span: 1
PRI Span: 1 > TEI: 0 State 7(Multi-frame established)
PRI Span: 1 > V(A)=17, V(S)=17, V(R)=73
PRI Span: 1 > K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 > T200_id=0, N200=3, T203_id=0
PRI Span: 1 > [ 00 01 01 93 ]
PRI Span: 1 > Supervisory frame:
PRI Span: 1 > SAPI: 00  C/R: 0 EA: 0
PRI Span: 1 >  TEI: 000        EA: 1
PRI Span: 1 > Zero: 0     S: 0 01: 1  [ RR (receive ready) ]
PRI Span: 1 > N(R): 073 P/F: 1
PRI Span: 1 > 0 bytes of data
PRI Span: 1 -- Starting T200 timer
PRI Span: 1
PRI Span: 1 < TEI: 0 State 8(Timer recovery)
PRI Span: 1 < V(A)=17, V(S)=17, V(R)=73
PRI Span: 1 < K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 < T200_id=8192, N200=3, T203_id=0
PRI Span: 1 < [ 02 01 01 23 ]
PRI Span: 1 < Supervisory frame:
PRI Span: 1 < SAPI: 00  C/R: 1 EA: 0
PRI Span: 1 <  TEI: 000        EA: 1
PRI Span: 1 < Zero: 0     S: 0 01: 1  [ RR (receive ready) ]
PRI Span: 1 < N(R): 017 P/F: 1
PRI Span: 1 < 0 bytes of data
PRI Span: 1
PRI Span: 1 > TEI: 0 State 8(Timer recovery)
PRI Span: 1 > V(A)=17, V(S)=17, V(R)=73
PRI Span: 1 > K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 > T200_id=8192, N200=3, T203_id=0
PRI Span: 1 > [ 02 01 01 93 ]
PRI Span: 1 > Supervisory frame:
PRI Span: 1 > SAPI: 00  C/R: 1 EA: 0
PRI Span: 1 >  TEI: 000        EA: 1
PRI Span: 1 > Zero: 0     S: 0 01: 1  [ RR (receive ready) ]
PRI Span: 1 > N(R): 073 P/F: 1
PRI Span: 1 > 0 bytes of data
PRI Span: 1 -- Got ACK for N(S)=17 to (but not including) N(S)=17
PRI Span: 1 Done handling message for SAPI/TEI=0/0
PRI Span: 1
PRI Span: 1 < TEI: 0 State 8(Timer recovery)
PRI Span: 1 < V(A)=17, V(S)=17, V(R)=73
PRI Span: 1 < K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 < T200_id=8192, N200=3, T203_id=0
PRI Span: 1 < [ 00 01 01 23 ]
PRI Span: 1 < Supervisory frame:
PRI Span: 1 < SAPI: 00  C/R: 0 EA: 0
PRI Span: 1 <  TEI: 000        EA: 1
PRI Span: 1 < Zero: 0     S: 0 01: 1  [ RR (receive ready) ]
PRI Span: 1 < N(R): 017 P/F: 1
PRI Span: 1 < 0 bytes of data
PRI Span: 1 -- Got ACK for N(S)=17 to (but not including) N(S)=17
PRI Span: 1 -- Stopping T200 timer
PRI Span: 1 -- Starting T203 timer
PRI Span: 1 Done handling message for SAPI/TEI=0/0
   == Using SIP RTP CoS mark 5
     -- Executing [998XXXX at business:1] Dial("SIP/bolongo-00001c78", 
"DAHDI/g0/998XXXX,60") in new stack
PRI Span: 1 -- Making new call for cref 32897
     -- Requested transfer capability: 0x00 - SPEECH
PRI Span: 1
PRI Span: 1 > DL-DATA request
PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=56
PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 129/0x81) (Sent from 
originator)
PRI Span: 1 > Message Type: SETUP (5)
PRI Span: 1 TEI=0 Transmitting N(S)=17, window is open V(A)=17 K=7
PRI Span: 1
PRI Span: 1 > TEI: 0 State 7(Multi-frame established)
PRI Span: 1 > V(A)=17, V(S)=17, V(R)=73
PRI Span: 1 > K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 > T200_id=0, N200=3, T203_id=8192
PRI Span: 1 > [ 00 01 22 92 08 02 00 81 05 04 03 80 90 a2 18 03 a1 83 81 
1e 02 80 83 28 0b b1 33 34 30 37 37 35 31 38 30 30 6c 0c 21 80 33 34 30 
37 37 35 31 38 30 30 70 08 80 39 39 38 39 39 36 35 ]
PRI Span: 1 > Informational frame:
PRI Span: 1 > SAPI: 00  C/R: 0 EA: 0
PRI Span: 1 >  TEI: 000        EA: 1
PRI Span: 1 > N(S): 017   0: 0
PRI Span: 1 > N(R): 073   P: 0
PRI Span: 1 > 56 bytes of data
PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=56
PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 129/0x81) (Sent from 
originator)
PRI Span: 1 > Message Type: SETUP (5)
PRI Span: 1 > [04 03 80 90 a2]
PRI Span: 1 > Bearer Capability (len= 5) [ Ext: 1  Coding-Std: 0 Info 
transfer capability: Speech (0)
PRI Span: 1 >                              Ext: 1  Trans mode/rate: 
64kbps, circuit-mode (16)
PRI Span: 1 >                                User information layer 1: 
u-Law (34)
PRI Span: 1 > [18 03 a1 83 81]
PRI Span: 1 > Channel ID (len= 5) [ Ext: 1  IntID: Implicit Other(PRI)  
Spare: 0  Preferred  Dchan: 0
PRI Span: 1 >                       ChanSel: As indicated in following 
octets
PRI Span: 1 >                       Ext: 1  Coding: 0  Number Specified  
Channel Type: 3
PRI Span: 1 >                       Ext: 1  Channel: 1 Type: CPE]
PRI Span: 1 > [1e 02 80 83]
PRI Span: 1 > Progress Indicator (len= 4) [ Ext: 1  Coding: CCITT (ITU) 
standard (0)  0: 0  Location: User (0)
PRI Span: 1 >                               Ext: 1  Progress 
Description: Calling equipment is non-ISDN. (3) ]
PRI Span: 1 > [28 0b b1 33 34 30 37 37 35 31 38 30 30]
PRI Span: 1 > Display (len=11) Charset: 31 [ 340NXXXXXX ]
PRI Span: 1 > [6c 0c 21 80 33 34 30 37 37 35 31 38 30 30]
PRI Span: 1 > Calling Party Number (len=14) [ Ext: 0  TON: National 
Number (2)  NPI: ISDN/Telephony Numbering Plan (E.164/E.163) (1)
PRI Span: 1 >                                 Presentation: Presentation 
allowed, User-provided, not screened (0)  '340NXXXXXX' ]
PRI Span: 1 > [70 08 80 39 39 38 39 39 36 35]
PRI Span: 1 > Called Party Number (len=10) [ Ext: 1  TON: Unknown Number 
Type (0)  NPI: Unknown Number Plan (0)  '998XXXX' ]
PRI Span: 1 -- Stopping T203 timer
PRI Span: 1 -- Starting T200 timer
PRI Span: 1 q931.c:6350 q931_setup: Call 32897 enters state 1 (Call 
Initiated).  Hold state: Idle
     -- Called DAHDI/g0/998XXXX
PRI Span: 1
PRI Span: 1 < TEI: 0 State 7(Multi-frame established)
PRI Span: 1 < V(A)=17, V(S)=18, V(R)=73
PRI Span: 1 < K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 < T200_id=8192, N200=3, T203_id=0
PRI Span: 1 < [ 00 01 01 24 ]
PRI Span: 1 < Supervisory frame:
PRI Span: 1 < SAPI: 00  C/R: 0 EA: 0
PRI Span: 1 <  TEI: 000        EA: 1
PRI Span: 1 < Zero: 0     S: 0 01: 1  [ RR (receive ready) ]
PRI Span: 1 < N(R): 018 P/F: 0
PRI Span: 1 < 0 bytes of data
PRI Span: 1 -- Got ACK for N(S)=17 to (but not including) N(S)=18
PRI Span: 1 -- ACKing N(S)=17, tx_queue head is N(S)=-1 (-1 is empty, -2 
is not transmitted)
PRI Span: 1 -- Stopping T200 timer
PRI Span: 1 -- Starting T203 timer
PRI Span: 1 Done handling message for SAPI/TEI=0/0
PRI Span: 1
PRI Span: 1 < TEI: 0 State 7(Multi-frame established)
PRI Span: 1 < V(A)=18, V(S)=18, V(R)=73
PRI Span: 1 < K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 < T200_id=0, N200=3, T203_id=8192
PRI Span: 1 < [ 02 01 92 24 08 02 80 81 02 18 03 a9 83 81 ]
PRI Span: 1 < Informational frame:
PRI Span: 1 < SAPI: 00  C/R: 1 EA: 0
PRI Span: 1 <  TEI: 000        EA: 1
PRI Span: 1 < N(S): 073   0: 0
PRI Span: 1 < N(R): 018   P: 0
PRI Span: 1 < 10 bytes of data
PRI Span: 1 < Protocol Discriminator: Q.931 (8)  len=10
PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 129/0x81) (Sent to 
originator)
PRI Span: 1 < Message Type: CALL PROCEEDING (2)
PRI Span: 1 < [18 03 a9 83 81]
PRI Span: 1 < Channel ID (len= 5) [ Ext: 1  IntID: Implicit Other(PRI)  
Spare: 0  Exclusive  Dchan: 0
PRI Span: 1 <                       ChanSel: As indicated in following 
octets
PRI Span: 1 <                       Ext: 1  Coding: 0  Number Specified  
Channel Type: 3
PRI Span: 1 <                       Ext: 1  Channel: 1 Type: CPE]
PRI Span: 1 -- Got ACK for N(S)=18 to (but not including) N(S)=18
PRI Span: 1 -- T200 requested to stop when not started
PRI Span: 1 T203 requested to start without stopping first
PRI Span: 1 -- Starting T203 timer
PRI Span: 1 Received message for call 0x7f73b8003940 on link 
0x7f73c0031500 TEI/SAPI 0/0
PRI Span: 1 -- Processing IE 24 (cs0, Channel ID)
PRI Span: 1 q931.c:8846 post_handle_q931_message: Call 32897 enters 
state 3 (Outgoing Call Proceeding).  Hold state: Idle
PRI Span: 1
PRI Span: 1 > TEI: 0 State 7(Multi-frame established)
PRI Span: 1 > V(A)=18, V(S)=18, V(R)=74
PRI Span: 1 > K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 > T200_id=0, N200=3, T203_id=8192
PRI Span: 1 > [ 02 01 01 94 ]
PRI Span: 1 > Supervisory frame:
PRI Span: 1 > SAPI: 00  C/R: 1 EA: 0
PRI Span: 1 >  TEI: 000        EA: 1
PRI Span: 1 > Zero: 0     S: 0 01: 1  [ RR (receive ready) ]
PRI Span: 1 > N(R): 074 P/F: 0
PRI Span: 1 > 0 bytes of data
PRI Span: 1 Done handling message for SAPI/TEI=0/0
Span 1: Processing event PRI_EVENT_PROCEEDING
     -- DAHDI/i1/998XXXX-fb is proceeding passing it to SIP/bolongo-00001c78
PRI Span: 1
PRI Span: 1 < TEI: 0 State 7(Multi-frame established)
PRI Span: 1 < V(A)=18, V(S)=18, V(R)=74
PRI Span: 1 < K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 < T200_id=0, N200=3, T203_id=8192
PRI Span: 1 < [ 02 01 94 24 08 02 80 81 45 08 02 80 9b ]
PRI Span: 1 < Informational frame:
PRI Span: 1 < SAPI: 00  C/R: 1 EA: 0
PRI Span: 1 <  TEI: 000        EA: 1
PRI Span: 1 < N(S): 074   0: 0
PRI Span: 1 < N(R): 018   P: 0
PRI Span: 1 < 9 bytes of data
PRI Span: 1 < Protocol Discriminator: Q.931 (8)  len=9
PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 129/0x81) (Sent to 
originator)
PRI Span: 1 < Message Type: DISCONNECT (69)
PRI Span: 1 < [08 02 80 9b]
PRI Span: 1 < Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  
Spare: 0  Location: User (0)
PRI Span: 1 <                  Ext: 1  Cause: Destination out of order 
(27), class = Normal Event (1) ]
PRI Span: 1 -- Got ACK for N(S)=18 to (but not including) N(S)=18
PRI Span: 1 -- T200 requested to stop when not started
PRI Span: 1 T203 requested to start without stopping first
PRI Span: 1 -- Starting T203 timer
PRI Span: 1 Received message for call 0x7f73b8003940 on link 
0x7f73c0031500 TEI/SAPI 0/0
PRI Span: 1 -- Processing IE 8 (cs0, Cause)
PRI Span: 1 -- Found active call: 0x7f73b8003940 cref:32897
PRI Span: 1 q931.c:9099 post_handle_q931_message: Call 32897 enters 
state 12 (Disconnect Indication).  Hold state: Idle
PRI Span: 1
PRI Span: 1 > TEI: 0 State 7(Multi-frame established)
PRI Span: 1 > V(A)=18, V(S)=18, V(R)=75
PRI Span: 1 > K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 > T200_id=0, N200=3, T203_id=8192
PRI Span: 1 > [ 02 01 01 96 ]
PRI Span: 1 > Supervisory frame:
PRI Span: 1 > SAPI: 00  C/R: 1 EA: 0
PRI Span: 1 >  TEI: 000        EA: 1
PRI Span: 1 > Zero: 0     S: 0 01: 1  [ RR (receive ready) ]
PRI Span: 1 > N(R): 075 P/F: 0
PRI Span: 1 > 0 bytes of data
PRI Span: 1 Done handling message for SAPI/TEI=0/0
Span 1: Processing event PRI_EVENT_HANGUP_REQ
     -- Span 1: Channel 0/1 got hangup request, cause 27
     -- DAHDI/i1/998XXXX-fb is circuit-busy
PRI Span: 1 q931.c:7151 q931_hangup: Hangup other cref:32897
PRI Span: 1 q931.c:6908 __q931_hangup: ourstate Disconnect Indication, 
peerstate Disconnect Request, hold-state Idle
PRI Span: 1 q931.c:5946 q931_release: Call 32897 enters state 19 
(Release Request).  Hold state: Idle
PRI Span: 1
PRI Span: 1 > DL-DATA request
PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=9
PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 129/0x81) (Sent from 
originator)
PRI Span: 1 > Message Type: RELEASE (77)
PRI Span: 1 TEI=0 Transmitting N(S)=18, window is open V(A)=18 K=7
PRI Span: 1
PRI Span: 1 > TEI: 0 State 7(Multi-frame established)
PRI Span: 1 > V(A)=18, V(S)=18, V(R)=75
PRI Span: 1 > K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 > T200_id=0, N200=3, T203_id=8192
PRI Span: 1 > [ 00 01 24 96 08 02 00 81 4d 08 02 81 9b ]
PRI Span: 1 > Informational frame:
PRI Span: 1 > SAPI: 00  C/R: 0 EA: 0
PRI Span: 1 >  TEI: 000        EA: 1
PRI Span: 1 > N(S): 018   0: 0
PRI Span: 1 > N(R): 075   P: 0
PRI Span: 1 > 9 bytes of data
PRI Span: 1 > Protocol Discriminator: Q.931 (8)  len=9
PRI Span: 1 > TEI=0 Call Ref: len= 2 (reference 129/0x81) (Sent from 
originator)
PRI Span: 1 > Message Type: RELEASE (77)
PRI Span: 1 > [08 02 81 9b]
PRI Span: 1 > Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0)  
Spare: 0  Location: Private network serving the local user (1)
PRI Span: 1 >                  Ext: 1  Cause: Destination out of order 
(27), class = Normal Event (1) ]
PRI Span: 1 -- Stopping T203 timer
PRI Span: 1 -- Starting T200 timer
     -- Hungup 'DAHDI/i1/998XXXX-fb'
   == Everyone is busy/congested at this time (1:0/1/0)
     -- Executing [998XXXX at business:2] Hangup("SIP/bolongo-00001c78", 
"") in new stack
   == Spawn extension (business, 998XXXX, 2) exited non-zero on 
'SIP/bolongo-00001c78'
PRI Span: 1
PRI Span: 1 < TEI: 0 State 7(Multi-frame established)
PRI Span: 1 < V(A)=18, V(S)=19, V(R)=75
PRI Span: 1 < K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 < T200_id=8192, N200=3, T203_id=0
PRI Span: 1 < [ 00 01 01 26 ]
PRI Span: 1 < Supervisory frame:
PRI Span: 1 < SAPI: 00  C/R: 0 EA: 0
PRI Span: 1 <  TEI: 000        EA: 1
PRI Span: 1 < Zero: 0     S: 0 01: 1  [ RR (receive ready) ]
PRI Span: 1 < N(R): 019 P/F: 0
PRI Span: 1 < 0 bytes of data
PRI Span: 1 -- Got ACK for N(S)=18 to (but not including) N(S)=19
PRI Span: 1 -- ACKing N(S)=18, tx_queue head is N(S)=-1 (-1 is empty, -2 
is not transmitted)
PRI Span: 1 -- Stopping T200 timer
PRI Span: 1 -- Starting T203 timer
PRI Span: 1 Done handling message for SAPI/TEI=0/0
PRI Span: 1
PRI Span: 1 < TEI: 0 State 7(Multi-frame established)
PRI Span: 1 < V(A)=19, V(S)=19, V(R)=75
PRI Span: 1 < K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 < T200_id=0, N200=3, T203_id=8192
PRI Span: 1 < [ 02 01 96 26 08 02 80 81 5a ]
PRI Span: 1 < Informational frame:
PRI Span: 1 < SAPI: 00  C/R: 1 EA: 0
PRI Span: 1 <  TEI: 000        EA: 1
PRI Span: 1 < N(S): 075   0: 0
PRI Span: 1 < N(R): 019   P: 0
PRI Span: 1 < 5 bytes of data
PRI Span: 1 < Protocol Discriminator: Q.931 (8)  len=5
PRI Span: 1 < TEI=0 Call Ref: len= 2 (reference 129/0x81) (Sent to 
originator)
PRI Span: 1 < Message Type: RELEASE COMPLETE (90)
PRI Span: 1 -- Got ACK for N(S)=19 to (but not including) N(S)=19
PRI Span: 1 -- T200 requested to stop when not started
PRI Span: 1 T203 requested to start without stopping first
PRI Span: 1 -- Starting T203 timer
PRI Span: 1 Received message for call 0x7f73b8003940 on link 
0x7f73c0031500 TEI/SAPI 0/0
PRI Span: 1 q931.c:8959 post_handle_q931_message: Call 32897 enters 
state 0 (Null).  Hold state: Idle
PRI Span: 1 q931.c:7151 q931_hangup: Hangup other cref:32897
PRI Span: 1 q931.c:6908 __q931_hangup: ourstate Null, peerstate Null, 
hold-state Idle
PRI Span: 1 Destroying call 0x7f73b8003940, ourstate Null, peerstate 
Null, hold-state Idle
PRI Span: 1
PRI Span: 1 > TEI: 0 State 7(Multi-frame established)
PRI Span: 1 > V(A)=19, V(S)=19, V(R)=76
PRI Span: 1 > K=7, RC=0, l3_initiated=0, reject_except=0, ack_pend=0
PRI Span: 1 > T200_id=0, N200=3, T203_id=8192
PRI Span: 1 > [ 02 01 01 98 ]
PRI Span: 1 > Supervisory frame:
PRI Span: 1 > SAPI: 00  C/R: 1 EA: 0
PRI Span: 1 >  TEI: 000        EA: 1
PRI Span: 1 > Zero: 0     S: 0 01: 1  [ RR (receive ready) ]
PRI Span: 1 > N(R): 076 P/F: 0
PRI Span: 1 > 0 bytes of data
PRI Span: 1 Done handling message for SAPI/TEI=0/0
Span 1: Processing event PRI_EVENT_HANGUP_ACK
astsouth*CLI> pri set debug off span 1
Disabled debugging on span 1

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20140820/6f35428c/attachment.html>