29 Oct
2013
29 Oct
'13
4:59 p.m.
I am more and more sure that the my failing handover situation has a
deeper root cause and it is not actually the handover which is
failing, but there should be a channel allocation problem. And there
it is.
The following log is made during the send of an SMS to the mobile from
the BSC CLI:
Tue Oct 29 15:06:15 2013 <001e> sms_queue.c:220 Attempting to send 20 SMS
Tue Oct 29 15:06:15 2013 <0000> chan_alloc.c:457 (bts=0,trx=0,ts=0,ss=1) starting
release sequence
Tue Oct 29 15:06:15 2013 <0000> abis_rsl.c:892 (bts=0,trx=0,ts=0,ss=1) RSL RLL
RELEASE REQ (link_id=0x03, reason=1)
Tue Oct 29 15:06:15 2013 <0003> gsm_04_08_utils.c:231 Sending Channel Release: Chan:
Number: 1 Type: 1
Tue Oct 29 15:06:15 2013 <0004> abis_rsl.c:634 (bts=0,trx=0,ts=0,ss=1) DEACTivate
SACCH CMD
Tue Oct 29 15:06:15 2013 <0004> abis_rsl.c:1070 (bts=0,trx=0,ts=0,ss=1): MEAS RES
for inactive channel
Tue Oct 29 15:06:15 2013 <001a> input/dahdi.c:320 send returns -1 instead of 160
Tue Oct 29 15:06:15 2013 <001a> input/dahdi.c:320 send returns -1 instead of 160
Tue Oct 29 15:06:15 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=1) SAPI=0
RELEASE INDICATION
Tue Oct 29 15:06:15 2013 <0004> abis_rsl.c:1628 (bts=0,trx=0,ts=0,ss=1) waiting for
SAPI=3 to be released.
Tue Oct 29 15:06:21 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=1) SAPI=3 Tue
Oct 29 15:06:21 2013 <0000> abis_rsl.c:1599 (bts=0,trx=0,ts=0,ss=1) ERROR INDICATION
cause=Timer T200 expired (N200+1) times
Tue Oct 29 15:06:21 2013 <0004> abis_rsl.c:680 (bts=0,trx=0,ts=0,ss=1) RF Channel
Release CMD due error 1
Tue Oct 29 15:06:21 2013 <0004> abis_rsl.c:634 (bts=0,trx=0,ts=0,ss=1) DEACTivate
SACCH CMD
Tue Oct 29 15:06:21 2013 <0000> abis_rsl.c:892 (bts=0,trx=0,ts=0,ss=1) RSL RLL
RELEASE REQ (link_id=0x03, reason=1)
Tue Oct 29 15:06:21 2013 <0004> abis_rsl.c:732 (bts=0,trx=0,ts=0,ss=1) RF CHANNEL
RELEASE ACK
Tue Oct 29 15:06:23 2013 <0004> abis_rsl.c:649 (bts=0,trx=0,ts=0,ss=1) is back in
operation.
As you can see, although SAPI=3 was requested to be release, we never
got any RELEASE INDICATION for that. And after some time, the radio
link will be disconnected with T200 timeout.
I tried to send another SMS the same way like above, and get a more
interesting log:
Tue Oct 29 15:54:45 2013 <001e> sms_queue.c:220 Attempting to send 20 SMS
Tue Oct 29 15:54:46 2013 <0000> chan_alloc.c:457 (bts=0,trx=0,ts=0,ss=1) starting
release sequence
Tue Oct 29 15:54:46 2013 <0000> abis_rsl.c:892 (bts=0,trx=0,ts=0,ss=1) RSL RLL
RELEASE REQ (link_id=0x03, reason=1)
Tue Oct 29 15:54:46 2013 <0003> gsm_04_08_utils.c:231 Sending Channel Release: Chan:
Number: 1 Type: 1
Tue Oct 29 15:54:46 2013 <0004> abis_rsl.c:634 (bts=0,trx=0,ts=0,ss=1) DEACTivate
SACCH CMD
Tue Oct 29 15:54:46 2013 <001a> input/dahdi.c:320 send returns -1 instead of 160
Tue Oct 29 15:54:46 2013 <001a> input/dahdi.c:320 send returns -1 instead of 160
Tue Oct 29 15:54:46 2013 <0004> abis_rsl.c:1070 (bts=0,trx=0,ts=0,ss=1): MEAS RES
for inactive channel
Tue Oct 29 15:54:46 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=1) SAPI=0
RELEASE INDICATION
Tue Oct 29 15:54:46 2013 <0004> abis_rsl.c:1628 (bts=0,trx=0,ts=0,ss=1) waiting for
SAPI=3 to be released.
...
Tue Oct 29 16:00:46 2013 <0004> abis_rsl.c:1467 (bts=0,trx=0,ts=0,ss=2) Activating
ARFCN(885) SS(2) lctype SDCCH r=LOCATION_UPDATE ra=0x08 ta=0
Tue Oct 29 16:00:46 2013 <0004> abis_rsl.c:1169 (bts=0,trx=0,ts=0,ss=2) CHANNEL
ACTIVATE ACK
As you can see, SAPI=3 again not getting released properly, but this
time there is not even a T200 timeout and the SACCH channel got stuck,
never released. The last two line is the periodic LA update, and you can see
that it uses ss=2, because the BSC thinks that ss=1 is still in use.
This is the very same issue I noticed with the handover:
[0;mFri Jul 26 12:45:29 2013 <000c> handover_decision.c:203 (bts=0,trx=0,ts=2):
Cell on ARFCN 123 is better: [0;mFri Jul 26 12:45:29 2013 <000c>
handover_logic.c:96 (old_lchan on BTS 0, new BTS 1)
[0;mStarting handover
[0;m[1;35mFri Jul 26 12:45:29 2013 <0004> abis_rsl.c:1165 (bts=1,trx=0,ts=2,ss=0)
CHANNEL ACTIVATE ACK
[0;mFri Jul 26 12:45:29 2013 <000c> handover_logic.c:204 handover activate ack,
send HO Command
[0;m[1;35mFri Jul 26 12:45:29 2013 <0004> abis_rsl.c:1138 (bts=1,trx=0,ts=2,ss=0)
HANDOVER DETECT [0;m[1;35maccess delay = 0
[0;m[1;31mFri Jul 26 12:45:29 2013 <0000> abis_rsl.c:1621 (bts=1,trx=0,ts=2,ss=0)
SAPI=0 [0;m[1;31mESTABLISH INDICATION
[0;m[1;31mFri Jul 26 12:45:29 2013 <0000> abis_rsl.c:1621 (bts=1,trx=0,ts=2,ss=0)
SAPI=0 [0;m[1;31mDATA INDICATION
[0;m[1;34mFri Jul 26 12:45:29 2013 <0003> bsc_api.c:515 HANDOVER COMPLETE cause =
Normal event
[0;mFri Jul 26 12:45:29 2013 <000c> handover_logic.c:261 Subscriber 244153333330126
HO from BTS 0->1 on ARFCN 885->123
[0;m[1;31mFri Jul 26 12:45:29 2013 <0000> chan_alloc.c:405 (bts=0,trx=0,ts=2,ss=0)
starting release sequence
[0;m[1;31mFri Jul 26 12:45:29 2013 <0000> abis_rsl.c:891 (bts=0,trx=0,ts=2,ss=0)
RSL RLL RELEASE REQ (link_id=0x00, reason=1)
[0;m[1;35mFri Jul 26 12:45:29 2013 <0004> abis_rsl.c:1069 (bts=0,trx=0,ts=2,ss=0):
MEAS RES for inactive channel
[0;m[1;35mFri Jul 26 12:45:30 2013 <0004> abis_rsl.c:1069 (bts=0,trx=0,ts=2,ss=0):
MEAS RES for inactive channel
[0;m[1;35mFri Jul 26 12:45:30 2013 <0004> abis_rsl.c:1069 (bts=0,trx=0,ts=2,ss=0):
MEAS RES for inactive channel
......
[0;m[1;35mFri Jul 26 12:45:40 2013 <0004> abis_rsl.c:1069 (bts=0,trx=0,ts=2,ss=0):
MEAS RES for inactive channel
[0;m[1;35mFri Jul 26 12:45:42 2013 <0004> abis_rsl.c:1069 (bts=0,trx=0,ts=2,ss=0):
MEAS RES for inactive channel
[0;m[1;35mFri Jul 26 12:45:43 2013 <0004> abis_rsl.c:1069 (bts=0,trx=0,ts=2,ss=0):
MEAS RES for inactive channel
[0;m[1;35mFri Jul 26 12:45:44 2013 <0004> abis_rsl.c:1069 (bts=0,trx=0,ts=2,ss=0):
MEAS RES for inactive channel
[0;m[1;35mFri Jul 26 12:45:44 2013 <0004> abis_rsl.c:988 (bts=0,trx=0,ts=2,ss=0)
CONNECTION FAIL: RELEASING [0;m[1;35mCAUSE=0x01(Radio Link Failure) [0;m[1;35m
[0;m[1;35mFri Jul 26 12:45:44 2013 <0004> abis_rsl.c:679 (bts=0,trx=0,ts=2,ss=0)
RF Channel Release CMD due error 1
[0;m[1;35mFri Jul 26 12:45:44 2013 <0004> abis_rsl.c:633 (bts=0,trx=0,ts=2,ss=0)
DEACTivate SACCH CMD
[0;m[1;31mFri Jul 26 12:45:44 2013 <0000> abis_rsl.c:891 (bts=0,trx=0,ts=2,ss=0)
RSL RLL RELEASE REQ (link_id=0x40, reason=1)
[0;m[1;35mFri Jul 26 12:45:44 2013 <0004> abis_rsl.c:1069 (bts=0,trx=0,ts=2,ss=0):
MEAS RES for inactive channel
[0;m[1;35mFri Jul 26 12:45:44 2013 <0004> abis_rsl.c:731 (bts=0,trx=0,ts=2,ss=0)
RF CHANNEL RELEASE ACK
[0;m[1;35mFri Jul 26 12:45:46 2013 <0004> abis_rsl.c:648 (bts=0,trx=0,ts=2,ss=0)
is back in operation.
As you can see, from the BSC point of view the handover was
successful, but it was not able to release the old channel, we never
got any RELEASE INDICATION. This is why we get the Radio Link Failure
eventually, because the phone is not there anymore, but the channel
yet not closed. Because the release of the old channel is not
successful, OpenBSC never tries to remap the TRAU to the new channel,
therefore both phones got disconnected (properly).
This is as far as I can get with this problem. Maybe now that I
narrowed down the root cause, someone can help me with it.
I still think this problem is not Nokia specific, maybe other BTSes
are affected (BS11 or other E1 based units).
Csaba