[Asterisk-Users] E1 PRI error: "!! Got I-frame while link state 2" and "!! Got a UA, but i'm in state 1" (long)

Dinesh Nair dinesh at alphaque.com
Thu Oct 20 07:44:17 MST 2005 

steve, konstanin,

On 10/20/05 13:56 steve at daviesfam.org said the following:
> This boils down to "I'm trying to start up the link, but the other side 
> seems to think that it IS up".

that's the same conclusion i came to, but why is this happenning ? changing 
loopback cables didnt help either.

> clocking, some for external.  If you are using loopback cables, I'd 
> suggest setting all the spans for internal (X,0,0,ccs,hdb3[,crc4])

tried two suggestions, one was yours with all spans set for timing=0, and 
the other was to have one set to 0, one set to 1, one set to 2 and one set 
to 3. in both cases, the symptoms persisted.

> And the loopback wiring is the pair on 1/2 crossed over to the pair on 
> 4/5.

aye, double checked this as well.

> The part you posted is just where Asterisk is restarting each B-channel.  
> More useful would be the part corresponding to the debug messages logged 
> above.

there're none for those portions. nothing gets printed, even though pri 
debug span is on. i could turn on pri intense debug, but would anyone be 
able to assist in deciphering it ?

when i try to make a call with the following call file,

Channel: Zap/g4/0193116969
MaxRetries: 0
RetryTime: 60
WaitTime: 30
Context: testplan
Extension: 12
Priority: 1

(the zap channels are set to context=zapin which does,
[zapin]
exten => s,1,Answer()
exten => s,2,Playback(demo-echotest)
exten => s,3,Goto(zapin,s,2)
exten => s,4,Hangup()

[testplan]
exten => 12,1,Answer()
exten => 12,2,Directory(default,localextensions,f)
exten => 12,3,Hangup()

*CLI> !cp /tmp/1.call /var/spool/asterisk/outgoing
     -- Attempting call on Zap/g4/0193116969 for 12 at testplan:1 (Retry 1)
     -- Requested transfer capability: 0x00 - SPEECH
     -- Going to extension s|1 because of immediate=yes
     -- Accepting call from '' to 's' on channel 0/4, span 1
     -- Executing Answer("Zap/4-1", "") in new stack
     -- Executing Playback("Zap/4-1", "demo-echotest") in new stack
     -- Playing 'demo-echotest' (language 'en')
Oct 21 06:33:03 NOTICE[280]: channel.c:2166 __ast_request_and_dial: Don't 
know what to do with control frame 15
   == Primary D-Channel on span 1 down
Oct 21 06:33:07 WARNING[280]: chan_zap.c:2265 pri_find_dchan: No D-channels 
available!  Using Primary channel 16 as D-channel anyway!
     -- Hungup 'Zap/4-1'
!! Got I-frame while link state 2
   == Primary D-Channel on span 4 up
!! Got I-frame while link state 2
     -- Channel 0/4, span 4 got hangup request
   == Primary D-Channel on span 1 up
     -- Hungup 'Zap/97-1'

what does "Don't know what to do with control frame 15" mean ?

a pri debug on span 4 (a pri_cpe which is looped back to span 1, pri_net) 
shows,

     -- Attempting call on Zap/g4/0193116969 for 12 at testplan:1 (Retry 1)
     -- Making new call for cr 32771
     -- Requested transfer capability: 0x00 - SPEECH
 > Protocol Discriminator: Q.931 (8)  len=33
 > Call Ref: len= 2 (reference 3/0x3) (Originator)
 > Message type: SETUP (5)
 > [04 03 80 90 a3]
 > Bearer Capability (len= 5) [ Ext: 1  Q.931 Std: 0  Info transfer 
capability: Speech (0)
 >                              Ext: 1  Trans mode/rate: 64kbps, 
circuit-mode (16)
 >                              Ext: 1  User information layer 1: A-Law (35)
 > [18 03 a9 83 99]
 > Channel ID (len= 5) [ Ext: 1  IntID: Implicit, PRI Spare: 0, Exclusive 
Dchan: 0
 >                        ChanSel: Reserved
 >                       Ext: 1  Coding: 0   Number Specified   Channel Type: 3
 >                       Ext: 1  Channel: 25 ]
 > [6c 02 00 c3]
 > Calling Number (len= 4) [ Ext: 0  TON: Unknown Number Type (0)  NPI: 
Unknown Number Plan (0)
 >                           Presentation: Number not available (67) '' ]
 > [70 0b 80 30 31 39 33 31 31 36 39 36 39]
 > Called Number (len=13) [ Ext: 1  TON: Unknown Number Type (0)  NPI: 
Unknown Number Plan (0) '0193116969' ]
 > [a1]
 > Sending Complete (len= 1)

     -- Going to extension s|1 because of immediate=yes
     -- Accepting call from '' to 's' on channel 0/25, span 1
     -- Executing Answer("Zap/25-1", "") in new stack
     -- Executing Playback("Zap/25-1", "demo-echotest") in new stack
     -- Playing 'demo-echotest' (language 'en')
< Protocol Discriminator: Q.931 (8)  len=10
< Call Ref: len= 2 (reference 3/0x3) (Terminator)
< Message type: CALL PROCEEDING (2)
< [18 03 a9 83 99]
< Channel ID (len= 5) [ Ext: 1  IntID: Implicit, PRI Spare: 0, Exclusive 
Dchan: 0
<                        ChanSel: Reserved
<                       Ext: 1  Coding: 0   Number Specified   Channel Type: 3
<                       Ext: 1  Channel: 25 ]
-- Processing IE 24 (cs0, Channel Identification)
Oct 21 06:25:35 NOTICE[123]: channel.c:2166 __ast_request_and_dial: Don't 
know what to do with control frame 15

 > Protocol Discriminator: Q.931 (8)  len=13
 > Call Ref: len= 2 (reference 0/0x0) (Originator)
 > Message type: RESTART (70)
 > [18 03 a9 83 9a]
 > Channel ID (len= 5) [ Ext: 1  IntID: Implicit, PRI Spare: 0, Exclusive 
Dchan: 0
 >                        ChanSel: Reserved
 >                       Ext: 1  Coding: 0   Number Specified   Channel Type: 3
 >                       Ext: 1  Channel: 26 ]
 > [79 01 80]
 > Restart Indentifier (len= 3) [ Ext: 1  Spare: 0  Resetting Indicated 
Channel (0) ]

   == Primary D-Channel on span 1 down
Oct 21 06:25:40 WARNING[123]: chan_zap.c:2265 pri_find_dchan: No D-channels 
available!  Using Primary channel 16 as D-channel anyway!

   == Spawn extension (default, s, 2) exited non-zero on 'Zap/25-1'
     -- Hungup 'Zap/25-1'

!! Got I-frame while link state 2

   == Primary D-Channel on span 4 up

!! Got I-frame while link state 2

< Protocol Discriminator: Q.931 (8)  len=9
< Call Ref: len= 2 (reference 3/0x3) (Terminator)
< Message type: DISCONNECT (69)
< [08 02 81 90]
< Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0) 0: 0 
Location: Private network serving the local user (1)
<                  Ext: 1  Cause: Unknown (16), class = Normal Event (1) ]
-- Processing IE 8 (cs0, Cause)
     -- Channel 0/25, span 4 got hangup request
!! Got I-frame while link state 2

   == Primary D-Channel on span 1 up
NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Disconnect Indication, 
peerstate Disconnect Request
 > Protocol Discriminator: Q.931 (8)  len=9
 > Call Ref: len= 2 (reference 3/0x3) (Originator)
 > Message type: RELEASE (77)
 > [08 02 81 90]
 > Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0) 0: 0 
Location: Private network serving the local user (1)
 >                  Ext: 1  Cause: Unknown (16), class = Normal Event (1) ]
     -- Hungup 'Zap/118-1'
Oct 21 06:25:40 NOTICE[123]: pbx_spool.c:254 attempt_thread: Call failed to 
go through, reason 1
ACK received for '1' outside of window of '0' to '0', restarting
   == Primary D-Channel on span 1 down
Oct 21 06:25:40 WARNING[123]: chan_zap.c:2265 pri_find_dchan: No D-channels 
available!  Using Primary channel 16 as D-channel anyway!
!! Got I-frame while link state 2
   == Primary D-Channel on span 4 up
   == Primary D-Channel on span 1 up

Timed out looking for release complete
 > Protocol Discriminator: Q.931 (8)  len=9
 > Call Ref: len= 2 (reference 3/0x3) (Originator)
 > Message type: RELEASE (77)
 > [08 02 81 90]
 > Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0) 0: 0 
Location: Private network serving the local user (1)
 >                  Ext: 1  Cause: Unknown (16), class = Normal Event (1) ]

< Protocol Discriminator: Q.931 (8)  len=9
< Call Ref: len= 2 (reference 3/0x3) (Terminator)
< Message type: RELEASE COMPLETE (90)
< [08 02 81 d1]
< Cause (len= 4) [ Ext: 1  Coding: CCITT (ITU) standard (0) 0: 0 
Location: Private network serving the local user (1)
<                  Ext: 1  Cause: Unknown (81), class = Invalid message (5) ]
-- Processing IE 8 (cs0, Cause)
NEW_HANGUP DEBUG: Calling q931_hangup, ourstate Null, peerstate Null
NEW_HANGUP DEBUG: Destroying the call, ourstate Null, peerstate Null

 > Protocol Discriminator: Q.931 (8)  len=13
 > Call Ref: len= 2 (reference 0/0x0) (Originator)
 > Message type: RESTART (70)
 > [18 03 a9 83 99]
 > Channel ID (len= 5) [ Ext: 1  IntID: Implicit, PRI Spare: 0, Exclusive 
Dchan: 0
 >                        ChanSel: Reserved
 >                       Ext: 1  Coding: 0   Number Specified   Channel Type: 3
 >                       Ext: 1  Channel: 25 ]
 > [79 01 80]
 > Restart Indentifier (len= 3) [ Ext: 1  Spare: 0  Resetting Indicated 
Channel (0) ]

   == Primary D-Channel on span 1 down
Oct 21 06:25:48 WARNING[123]: chan_zap.c:2265 pri_find_dchan: No D-channels 
available!  Using Primary channel 16 as D-channel anyway!

!! Got I-frame while link state 2

   == Primary D-Channel on span 4 up
!! Got I-frame while link state 2

   == Primary D-Channel on span 1 up

> I'm not sure how old your card is, but I routinely run the CVS-HEAD 
> zaptel/libpri/asterisk on generation 1, "version 10" cards.

wct4xxp.ko reports,

TE4XXP version c01a009b, burst ON, slip debug: OFF
FALC version: 00000005, Board ID: 00
TE4XXP: Launching card: 0
TE4XXP: Setting up global serial parameters
Found a Wildcard: Wildcard TE410P/TE405P (1st Gen)
Registered tone zone 19 (Malaysia)
TE410P: Span 1 configured for CCS/HDB3
TE410P: Span 2 configured for CCS/HDB3
TE410P: Span 3 configured for CCS/HDB3
TE410P: Span 4 configured for CCS/HDB3
wct4xxp: Setting yellow alarm on span 3
wct4xxp: Setting yellow alarm on span 4

card serial number, as printed on a sticker on the card, is 0057.

pri show span 1
Primary D-channel: 16
Status: Provisioned, Up, Active
Switchtype: EuroISDN
Type: Network
Q931 RX: 4
Q931 TX: 8
Q921 RX: 1516
Q921 TX: 1552
Q921 Outstanding: 0
Window Length: 0/7
Sentrej: 0
SolicitFbit: 0
Retrans: 0
Busy: 0
Overlap Dial: 0
T200 Timer: 1000
T203 Timer: 10000
T305 Timer: 30000
T308 Timer: 4000
T313 Timer: 4000
N200 Counter: 3

pri show span 4
Primary D-channel: 109
Status: Provisioned, Up, Active
Switchtype: EuroISDN
Type: CPE
Q931 RX: 5
Q931 TX: 10
Q921 RX: 2036
Q921 TX: 2313
Q921 Outstanding: 0
Window Length: 0/7
Sentrej: 0
SolicitFbit: 0
Retrans: 0
Busy: 0
Overlap Dial: 0
T200 Timer: 1000
T203 Timer: 10000
T305 Timer: 30000
T308 Timer: 4000
T313 Timer: 4000
N200 Counter: 3

> Unusual order here.  I've always followed the sample and put the span 
> definitions at the top and the bchan/dchan following.

i've amended that, still no luck.

> Also, see the comment about the "1" for taking clock - rather make it 0 
> for loopback tests.

i have. see attached zaptel.conf and zapata.conf.

> Did you leave out the other two spans in your zapata.conf?

i left it out for verbosity reasons. it does exist in zapata.conf.

> Its a bit unusual to put both spans in the same group - calls to Zap/g1 
> may use any channel on either of the spans.  Is that what you want?
> And immediate=yes is probably not what you want for an ISDN link.

what if we dont have DIDs, but want it answered anyways. as the verbose 
output above shows, asterisk knows about immediate=yes and pushes it to the 
s extension correctly.

-- 
Regards,                           /\_/\   "All dogs go to heaven."
dinesh at alphaque.com                (0 0)    http://www.alphaque.com/
+==========================----oOO--(_)--OOo----==========================+
| for a in past present future; do                                        |
|   for b in clients employers associates relatives neighbours pets; do   |
|   echo "The opinions here in no way reflect the opinions of my $a $b."  |
| done; done                                                              |
+=========================================================================+

-------------- next part --------------
[channels]
signalling=pri_net
context=default
group=1
callgroup=1
pickupgroup=1
priindication=outofband
switchtype=euroisdn
context=default
amaflags=default
busycount=4
callwaiting=no
transfer=yes
useincomingcalleridonzaptransfer=yes
threewaycalling=yes
callreturn=yes
relaxdtmf=no
busydetect=no
usecallerid=yes
hidecallerid=no
echocancel=yes
echocancelwhenbridged=no
echotraining=no
immediate=no
channel => 1-15
channel => 17-31
signalling=pri_cpe
context=default
group=1
callgroup=1
pickupgroup=1
priindication=outofband
switchtype=euroisdn
context=default
amaflags=default
busycount=4
callwaiting=no
transfer=yes
useincomingcalleridonzaptransfer=yes
threewaycalling=yes
callreturn=yes
relaxdtmf=no
busydetect=no
usecallerid=yes
hidecallerid=no
echocancel=yes
echocancelwhenbridged=no
echotraining=no
immediate=yes
channel => 32-46
channel => 48-62
signalling=pri_net
context=default
group=1
callgroup=1
pickupgroup=1
priindication=outofband
switchtype=euroisdn
context=default
amaflags=default
busycount=4
callwaiting=no
transfer=yes
useincomingcalleridonzaptransfer=yes
threewaycalling=yes
callreturn=yes
relaxdtmf=no
busydetect=no
usecallerid=yes
hidecallerid=no
echocancel=yes
echocancelwhenbridged=no
echotraining=no
immediate=yes
channel => 63-77
channel => 79-93
signalling=pri_cpe
context=default
group=1
callgroup=1
pickupgroup=1
priindication=outofband
switchtype=euroisdn
context=default
amaflags=default
busycount=4
callwaiting=no
transfer=yes
useincomingcalleridonzaptransfer=yes
threewaycalling=yes
callreturn=yes
relaxdtmf=no
busydetect=no
usecallerid=yes
hidecallerid=no
echocancel=yes
echocancelwhenbridged=no
echotraining=no
immediate=yes
channel => 94-108
channel => 110-124
-------------- next part --------------
loadzone=my
defaultzone=my
bchan=1-15
dchan=16
bchan=17-31
span=1,0,0,ccs,hdb3,crc4
bchan=32-46
dchan=47
bchan=48-62
span=2,1,0,ccs,hdb3,crc4
bchan=63-77
dchan=78
bchan=79-93
span=3,0,0,ccs,hdb3,crc4
bchan=94-108
dchan=109
bchan=110-124
span=4,1,0,ccs,hdb3,crc4

More information about the asterisk-users mailing list