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
On Tue, Oct 29, 2013 at 04:59:32PM +0100, Sipos Csaba wrote:
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
was SAPI=3 ever established? Is T3109 0 for you? You might want to change that too.
I still think this problem is not Nokia specific, maybe other BTSes are affected (BS11 or other E1 based units).
What is the issue with the BS11? Maybe it is something as simple as the local end release being nrpken in the Nokia BTS?
Hello Holger,
was SAPI=3 ever established?
Of cause it was established. Here is a complete log of the situation with SMS:
Tue Oct 29 21:21:40 2013 <001e> sms_queue.c:220 Attempting to send 20 SMS Tue Oct 29 21:21:42 2013 <0004> abis_rsl.c:1467 (bts=0,trx=0,ts=0,ss=0) Activating ARFCN(885) SS(0) lctype SDCCH r=LOCATION_UPDATE ra=0x16 ta=0 Tue Oct 29 21:21:42 2013 <0004> abis_rsl.c:1169 (bts=0,trx=0,ts=0,ss=0) CHANNEL ACTIVATE ACK Tue Oct 29 21:21:42 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=0) SAPI=0 ESTABLISH INDICATION Tue Oct 29 21:21:42 2013 <0003> gsm_04_08.c:1187 PAGING RESPONSE: mi_type=0x04 MI(2040770818) Tue Oct 29 21:21:42 2013 <0003> gsm_04_08.c:1205 <- Channel was requested by 244153333330127 Tue Oct 29 21:21:42 2013 <0001> transaction.c:69 subscr=0x9ad51f0, subscr->net=0x9a90248 Tue Oct 29 21:21:42 2013 <0000> abis_rsl.c:866 (bts=0,trx=0,ts=0,ss=0) RSL RLL ESTABLISH REQ (link_id=0x03) Tue Oct 29 21:21:42 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=0) SAPI=0 DATA INDICATION Tue Oct 29 21:21:42 2013 <0003> bsc_api.c:615 CLASSMARK CHANGE CM2(len=3) CM3(len=9) Tue Oct 29 21:21:42 2013 <001a> input/dahdi.c:320 send returns -1 instead of 160 Tue Oct 29 21:21:42 2013 <001a> input/dahdi.c:320 send returns -1 instead of 160 Tue Oct 29 21:21:43 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=0) SAPI=3 ESTABLISH CONFIRM Tue Oct 29 21:21:44 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=0) SAPI=3 DATA INDICATION Tue Oct 29 21:21:44 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=0) SAPI=3 DATA INDICATION Tue Oct 29 21:21:45 2013 <001e> sms_queue.c:220 Attempting to send 20 SMS Tue Oct 29 21:21:45 2013 <0000> chan_alloc.c:457 (bts=0,trx=0,ts=0,ss=0) starting release sequence Tue Oct 29 21:21:45 2013 <0000> abis_rsl.c:892 (bts=0,trx=0,ts=0,ss=0) RSL RLL RELEASE REQ (link_id=0x03, reason=1) Tue Oct 29 21:21:45 2013 <0003> gsm_04_08_utils.c:231 Sending Channel Release: Chan: Number: 0 Type: 1 Tue Oct 29 21:21:45 2013 <0004> abis_rsl.c:634 (bts=0,trx=0,ts=0,ss=0) DEACTivate SACCH CMD Tue Oct 29 21:21:45 2013 <0004> abis_rsl.c:1070 (bts=0,trx=0,ts=0,ss=0): MEAS RES for inactive channel Tue Oct 29 21:21:45 2013 <001a> input/dahdi.c:320 send returns -1 instead of 160 Tue Oct 29 21:21:45 2013 <001a> input/dahdi.c:320 send returns -1 instead of 160 Tue Oct 29 21:21:45 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=0) SAPI=0 RELEASE INDICATION Tue Oct 29 21:21:45 2013 <0004> abis_rsl.c:1628 (bts=0,trx=0,ts=0,ss=0) waiting for SAPI=3 to be released. Tue Oct 29 21:21:51 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=0) SAPI=3 Tue Oct 29 21:21:51 2013 <0000> abis_rsl.c:1599 (bts=0,trx=0,ts=0,ss=0) ERROR INDICATION cause=Timer T200 expired (N200+1) times Tue Oct 29 21:21:51 2013 <0004> abis_rsl.c:680 (bts=0,trx=0,ts=0,ss=0) RF Channel Release CMD due error 1 Tue Oct 29 21:21:51 2013 <0004> abis_rsl.c:634 (bts=0,trx=0,ts=0,ss=0) DEACTivate SACCH CMD Tue Oct 29 21:21:51 2013 <0000> abis_rsl.c:892 (bts=0,trx=0,ts=0,ss=0) RSL RLL RELEASE REQ (link_id=0x03, reason=1) Tue Oct 29 21:21:51 2013 <0004> abis_rsl.c:732 (bts=0,trx=0,ts=0,ss=0) RF CHANNEL RELEASE ACK Tue Oct 29 21:21:53 2013 <0004> abis_rsl.c:649 (bts=0,trx=0,ts=0,ss=0) is back in operation.
Is T3109 0 for you? You might want to change that too.
Yes, it was 0, I raised it to 10, but it doesn't change anything, all the problems still exists. Should I try and change other timers too?
Maybe it is something as simple as the local end release being nrpken in the Nokia BTS?
You mean the local end release being broken in the BTS? How can I find this out? I see your point, that the release command has been sent, but we never got any ACK or something like that back. But how is it possible that it works for SAPI=0 and it does not for SAPI=3 ? These units were used by big organizations to improve the indoor coverage, I really don't think that the BTS or its firmware is wrong by design.
Maybe OpenBSC destroys SAPI=0 too fast, and there is not enough time for this: <0000> abis_rsl.c:892 (bts=0,trx=0,ts=0,ss=0) RSL RLL RELEASE REQ (link_id=0x03, reason=1) to be ACKed by the BTS?
Here is another log from the failing handover initiated by the Openbsc VTY "handover" command. THe handover is failing even if I move the phone within the same TRX to another channel:
Silent call for the MS started (SDCCH): Tue Oct 29 21:28:37 2013 <0004> abis_rsl.c:1467 (bts=0,trx=0,ts=0,ss=0) Activating ARFCN(885) SS(0) lctype SDCCH r=LOCATION_UPDATE ra=0x1f ta=0 Tue Oct 29 21:28:37 2013 <0004> abis_rsl.c:1169 (bts=0,trx=0,ts=0,ss=0) CHANNEL ACTIVATE ACK Tue Oct 29 21:28:38 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=0) SAPI=0 ESTABLISH INDICATION Tue Oct 29 21:28:38 2013 <0003> gsm_04_08.c:1187 PAGING RESPONSE: mi_type=0x04 MI(2040680933) Tue Oct 29 21:28:38 2013 <0003> gsm_04_08.c:1205 <- Channel was requested by 244153333330127 Tue Oct 29 21:28:38 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=0,ss=0) SAPI=0 DATA INDICATION Tue Oct 29 21:28:38 2013 <0003> bsc_api.c:615 CLASSMARK CHANGE CM2(len=3) CM3(len=9) The handover command given in Openbsc VTY (% Handover started from (bts=0,trx=0,ts=0,ss=0) to (bts=0,trx=0,ts=2,ss=0): Tue Oct 29 21:28:50 2013 <000c> handover_logic.c:66 (BTS 0 (subscr 244153333330127)) Start Handover Tue Oct 29 21:28:50 2013 <0004> abis_rsl.c:1169 (bts=0,trx=0,ts=2,ss=0) CHANNEL ACTIVATE ACK Tue Oct 29 21:28:50 2013 <000c> handover_logic.c:66 (BTS 0 (subscr 244153333330127)) Channel activate ack, send HO/AS Command Tue Oct 29 21:28:51 2013 <0004> abis_rsl.c:1142 (bts=0,trx=0,ts=2,ss=0) HANDOVER DETECT access delay = 0 Tue Oct 29 21:28:51 2013 <000c> handover_logic.c:66 (BTS 0 (subscr 244153333330127)) Handover RACH detected Tue Oct 29 21:28:51 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=2,ss=0) SAPI=0 ESTABLISH INDICATION Tue Oct 29 21:28:51 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=2,ss=0) SAPI=0 DATA INDICATION Tue Oct 29 21:28:51 2013 <0003> bsc_api.c:651 HANDOVER COMPLETE cause = Normal event Tue Oct 29 21:28:51 2013 <000c> handover_logic.c:66 (BTS 0 (subscr 244153333330127)) Handover/Assignment completed Handover success from BSC point of view, but we have to close the old chan first: Tue Oct 29 21:28:51 2013 <0000> chan_alloc.c:457 (bts=0,trx=0,ts=0,ss=0) starting release sequence Tue Oct 29 21:28:51 2013 <0000> abis_rsl.c:892 (bts=0,trx=0,ts=0,ss=0) RSL RLL RELEASE REQ (link_id=0x00, reason=1) Tue Oct 29 21:28:51 2013 <0004> abis_rsl.c:1070 (bts=0,trx=0,ts=0,ss=0): MEAS RES for inactive channel ............................... Tue Oct 29 21:29:20 2013 <0004> abis_rsl.c:1070 (bts=0,trx=0,ts=0,ss=0): MEAS RES for inactive channel Which is not happening despite we given the command, and times out after "radio-link-timeout 16": Tue Oct 29 21:29:20 2013 <0004> abis_rsl.c:989 (bts=0,trx=0,ts=0,ss=0) CONNECTION FAIL: RELEASING CAUSE=0x01(Radio Link Failure) Tue Oct 29 21:29:20 2013 <0004> abis_rsl.c:680 (bts=0,trx=0,ts=0,ss=0) RF Channel Release CMD due error 1 Tue Oct 29 21:29:20 2013 <0004> abis_rsl.c:634 (bts=0,trx=0,ts=0,ss=0) DEACTivate SACCH CMD Tue Oct 29 21:29:20 2013 <0000> abis_rsl.c:892 (bts=0,trx=0,ts=0,ss=0) RSL RLL RELEASE REQ (link_id=0x00, reason=1) Tue Oct 29 21:29:20 2013 <0004> abis_rsl.c:1070 (bts=0,trx=0,ts=0,ss=0): MEAS RES for inactive channel Tue Oct 29 21:29:20 2013 <0004> abis_rsl.c:732 (bts=0,trx=0,ts=0,ss=0) RF CHANNEL RELEASE ACK Tue Oct 29 21:29:22 2013 <0004> abis_rsl.c:649 (bts=0,trx=0,ts=0,ss=0) is back in operation. The slient call is still working on the new channel, so I gave command to close it (silent-call stop): Tue Oct 29 21:29:49 2013 <0000> chan_alloc.c:457 (bts=0,trx=0,ts=2,ss=0) starting release sequence Tue Oct 29 21:29:49 2013 <0003> gsm_04_08_utils.c:231 Sending Channel Release: Chan: Number: 0 Type: 2 Tue Oct 29 21:29:49 2013 <0004> abis_rsl.c:634 (bts=0,trx=0,ts=2,ss=0) DEACTivate SACCH CMD Tue Oct 29 21:29:49 2013 <0004> abis_rsl.c:1070 (bts=0,trx=0,ts=2,ss=0): MEAS RES for inactive channel Tue Oct 29 21:29:49 2013 <0000> abis_rsl.c:1657 (bts=0,trx=0,ts=2,ss=0) SAPI=0 RELEASE INDICATION Tue Oct 29 21:29:49 2013 <0004> abis_rsl.c:680 (bts=0,trx=0,ts=2,ss=0) RF Channel Release CMD due error 0 Tue Oct 29 21:29:49 2013 <0004> abis_rsl.c:732 (bts=0,trx=0,ts=2,ss=0) RF CHANNEL RELEASE ACK
I hope someone can help me with this. I think we are close to solve this problem.
BR, Csaba
On Tue, Oct 29, 2013 at 11:01:24PM +0100, Sipos Csaba wrote:
You mean the local end release being broken in the BTS? How can I find this out? I see your point, that the release command has been sent, but we never got any ACK or something like that back. But how is it possible that it works for SAPI=0 and it does not for SAPI=3 ? These units were used by big organizations to improve the indoor coverage, I really don't think that the BTS or its firmware is wrong by design.
Maybe OpenBSC destroys SAPI=0 too fast, and there is not enough time for this:
Check rsl_release_sapis_from and the caller in _lchan_handle_release. First everything from 1 t X is released and the SACCH deactivated.
Play with that, or attempt to get a trace of a Nokia BTS with a Nokia BSC and look at there release procedure. E.g. if order or release requests kinds are different.
-
Holger Hans Peter Freyther -
Sipos Csaba