Cellular Network Infrastructure » Radio Access Network » OsmoBSC

I am not entirely finished with the implementation, but I think I am very close. I have a TTCN3 test that first activates all channels on the BTS (similar to TC_chan_exhaustion) and the tries a channel request for an emergency call. This test passes, I can see how one of the occupied TCH/F gets released and as soon as there i room for a the new channel I get the Channel Activation / CHannel Activation ACK.

However, when testing on hardware things look somewhat different. Things should work, but apparantly I am still having problems to detect the various lchan types properly.

The implementation is now complete and the patches are up for review. Unfortunately it turned out that due to a lack of CHANNEL MODE MODIFY functionality in osmo-bsc things were more complex as expected. The patches are now up for review.

Patches for osmo-bsc:
https://gerrit.osmocom.org/c/osmo-bsc/+/19790 lchan_fsm: merge lchan_mr_config()
https://gerrit.osmocom.org/c/osmo-bsc/+/19791 lchan_fsm: make internal functions static.
https://gerrit.osmocom.org/c/osmo-bsc/+/19792 lchan_fsm: make rsl mode-modify working again
https://gerrit.osmocom.org/c/osmo-bsc/+/19793 abis_rsl: prioritize emergency calls over regular calls

TTCN3 Testcase:
https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/19794 BSC_Tests: test emergency call preemption

I have now worked myself through the review comments of #19792 and #19793. I hope the patches are acceptable now. Getting rid of the timer based approach also showed an increase of performance while testing.

pespin: For the integration in the tester we would need to fill up all TCH/H and TCH/F with active calls. The SDCCH channels may remain free as emergency calls get TCH channels directly. When an emergency call is made, one of the occupied TCH will be dropped. At least that is what the scenario should look like.

pespin All patches are merged and TC_emerg_premption also passes in jenkins (setting the verdict in the end solved the problem, however the problem did not occur when executing the tests locally). We now need a test implementation on the tester, so I hand over this ticket to you.

I added a osmo-gsm-tester test to verify emergency call preemption here:
https://gerrit.osmocom.org/c/osmo-gsm-tester/+/20670 sysmocom: Introduce test to verify emergency call preemption

The test sometimes passes and sometimes doesn't. When it passes I can see from ofono point of view how the 2 MS running a normal call are dropped while the new emergency call between the other 2 MS works fine.
I'm attaching a pcap for a failing case (with dropped RTP packets).

At first glance it seems like a BSC issue (or perhaps MSC, not sure). When the new Emergency RACH request comes in, the BSC attempts to drop the SCCP conns towards the MSC:

[BSC gets Channel Required for MO Emergency call in pcap frame 5576]
BSC -> MSC: BSSMAP Clear Request (Destination Local Reference: 0x080000)
BSC <- MSC: CC Release (Destination Local Reference: 0x090000)
BSC <- MSC: BSSMAP Clear Command (Destination Local Reference: 0x090000)
[BSC finally sends Channel Activation to BTS, and gets a Channel Activation ACK]
BSC -> MSC: BSSMAP Clear Request (Destination Local Reference: 0x080000)  <--- REPEATED FROM ABOVE?!!!!
BSC -> MSC: BSSMAP Clear Complete (Destination Local Reference: 0x080000)
BSC <- MSC: SCCP RLSD (Source Local Reference: 0x080000, Destination Local Reference: 0x090000)

Looking further at the pcap trace the issue seems to happen much later though, when the emergency call is trying to be established. The MS seems to be answering the CC Setup with a Call Confirmed (frame 8819), and then MSC sends an Assignment Request to BSC (frame 8829) which after a while is rejected with an BSSMAP Assignment Failure (frame 9413). Looking at BSC logs:

20201015184804006 DCHAN <000f> fsm.c:322 lchan(0-0-2-TCH_F-0)[0x612000005320]{WAIT_RLL_RTP_ESTABLISH}: Timeout of T3101
20201015184804006 DCHAN <000f> lchan_fsm.c:1557 lchan(0-0-2-TCH_F-0)[0x612000005320]{WAIT_RLL_RTP_ESTABLISH}: (type=TCH_F) Handling failure, will then transition to state WAIT_RF_RELEASE_ACK
20201015184804007 DCHAN <000f> lchan_fsm.c:81 lchan(0-0-2-TCH_F-0)[0x612000005320]{WAIT_RLL_RTP_ESTABLISH}: (type=TCH_F) lchan allocation failed in state WAIT_RLL_RTP_ESTABLISH: Timeout
20201015184804007 DCHAN <000f> lchan_fsm.c:116 lchan(0-0-2-TCH_F-0)[0x612000005320]{WAIT_RLL_RTP_ESTABLISH}: (type=TCH_F) Signalling Assignment FSM of error (lchan allocation failed in state WAIT_RLL_RTP_ESTABLISH: Timeout)
20201015184804007 DAS <0011> lchan_fsm.c:1557 assignment(msc0-conn12_subscr-IMSI-901700000023847-TMSI-0x35a6a33d_0-0-2-TCH_F-0)[0x612000000520]{WAIT_RR_ASS_COMPLETE}: Received Event ASSIGNMENT_EV_LCHAN_ERROR
20201015184804007 DAS <0011> assignment_fsm.c:772 assignment(msc0-conn12_subscr-IMSI-901700000023847-TMSI-0x35a6a33d_0-0-2-TCH_F-0)[0x612000000520]{WAIT_RR_ASS_COMPLETE}: (bts=0,trx=0,ts=2,ss=0) Assignment failed in state WAIT_RR_ASS_COMPLETE, cause RADIO INTERFACE MESSAGE FAILURE: Failed to activate lchan (bts=0,trx=0,ts=2,ss=0)
20201015184804007 DAS <0011> assignment_fsm.c:772 assignment(msc0-conn12_subscr-IMSI-901700000023847-TMSI-0x35a6a33d_0-0-2-TCH_F-0)[0x612000000520]{WAIT_RR_ASS_COMPLETE}: (bts=0,trx=0,ts=2,ss=0) incrementing rate counter: assignment:error Assignment failed for other reason
20201015184804007 DMSC <0007> osmo_bsc_sigtran.c:378 Tx MSC: BSSMAP: ASSIGNMENT FAIL

I have tested the functionality of the emergency calling preemption again on my test network. This time my setup has two TCH/F channels and an asterisk backend. I can make two calls to numbers which play recordings (so I do not need to worry about MO/MT, all calls are MT). When I make another call to a recording one of the running calls gets cancelled. This works fine so far.

I was able to reproduce the problem with the duplicated CLEAR REQUEST. I also see a CLEAR REQUEST two times. Since I did manual testing this slipped through because everything else looked ok. The problem is in bsc_subscr_conn_fsm.c. I would expect the gscon fsm to change to the clearing state once it has sent the first clear request but the problem could also be at the MSC as well.

Here is the log from my setup:

First CLEAR REQUEST is when the lchan gets detached, this should be the first and only time where a CLEAR REQUEST is sent.

Sun Oct 18 22:40:50 2020 DCHAN <000f> lchan_fsm.c:1595 lchan(0-0-1-TCH_F-0)[0x562c1c1a0d20]{ESTABLISHED}: state_chg to WAIT_RF_RELEASE_ACK
Sun Oct 18 22:40:50 2020 DMSC <0007> bsc_subscr_conn_fsm.c:774 SUBSCR_CONN(msc0-conn19_subscr-IMSI-001010000000101-TMSI-0x96263ae7)[0x562c1c1b5cf0]{ACTIVE}: conn detaches lchan lchan(0-0-1-TCH_F-0)[0x562c1c1a0d20]
Sun Oct 18 22:40:50 2020 DCHAN <000f> bsc_subscr_conn_fsm.c:778 lchan(0-0-1-TCH_F-0)[0x562c1c1a0d20]{WAIT_RF_RELEASE_ACK}: conn SUBSCR_CONN(msc0-conn19_subscr-IMSI-001010000000101-TMSI-0x96263ae7)[0x562c1c1b5cf0] detaches lchan (primary lchan)
Sun Oct 18 22:40:50 2020 DMSC <0007> bsc_subscr_conn_fsm.c:157 SUBSCR_CONN(msc0-conn19_subscr-IMSI-001010000000101-TMSI-0x96263ae7)[0x562c1c1b5cf0]{ACTIVE}: Tx BSSMAP CLEAR REQUEST(EQUIPMENT FAILURE) to MSC
Sun Oct 18 22:40:50 2020 DMSC <0007> osmo_bsc_sigtran.c:379 Tx MSC: BSSMAP: CLEAR REQUEST

Here seems to come an MT_DTAP from the MSC, which causes another CLEAR_REQUEST. When I rethink this it might be also the MSC that is behaving wrongly. Is it still permitted to send MT_DTAP messages to the BSC when it has asked for clearing the connection? Maybe the MSC should block those messages and continue with the clearing?

Sun Oct 18 22:40:50 2020 DMSC <0007> osmo_bsc_bssap.c:1266 SUBSCR_CONN(msc0-conn19_subscr-IMSI-001010000000101-TMSI-0x96263ae7)[0x562c1c1b5cf0]{ACTIVE}: Received Event MT_DTAP
Sun Oct 18 22:40:50 2020 DMSC <0007> bsc_subscr_conn_fsm.c:1118 subscr-IMSI-001010000000101-TMSI-0x96263ae7 Called submit dtap without an lchan.
Sun Oct 18 22:40:50 2020 DMSC <0007> bsc_subscr_conn_fsm.c:1155 SUBSCR_CONN(msc0-conn19_subscr-IMSI-001010000000101-TMSI-0x96263ae7)[0x562c1c1b5cf0]{ACTIVE}: Tx BSSMAP CLEAR REQUEST to MSC
Sun Oct 18 22:40:50 2020 DMSC <0007> bsc_subscr_conn_fsm.c:157 SUBSCR_CONN(msc0-conn19_subscr-IMSI-001010000000101-TMSI-0x96263ae7)[0x562c1c1b5cf0]{ACTIVE}: Tx BSSMAP CLEAR REQUEST(EQUIPMENT FAILURE) to MSC
Sun Oct 18 22:40:50 2020 DMSC <0007> osmo_bsc_sigtran.c:379 Tx MSC: BSSMAP: CLEAR REQUEST

In the second problem you describe I guess something took too long. "Timeout of T3101" sounds not good. I wonder where to look in the pcap. The packet numbers seem not to match up. When I get you right this is an additional problem and the emergency call fails completely. It would be good to have the full log of this situation.

Attaching osmo-gsm-tester output (tar.bz2) with all logs, configs, etc. together with a pcap files taken with tcpdump on the main unit (removed TRXD and RTP).

So to clarify there's (at least) 2 different issues:
1- Duplicated BSSMAP Clear Request BSC->MSC
2- Asignment Failure answered by BSC upon Assignment Request by MSC of the MT side of the emergency call (forwarded to an MS).

Regarding 2, I guess it due to the second lef of the previous non-emergency call is not released, meaning there's only 1 TS freed which is then use by the MO side of the emergency call. Then we still need to free some TS space for the MT side in this case.

• BTS sending an "ERROR INDication" to BSC with cause: "Cause: SABM frame with information not allowed in this state (14)".
• The MS sending to the BTS in lapdm: "Assignment Failure" with cause "RR cause value: Protocol error unspecified (111)". But the BTS doesn't seem to be forwarding this to the BSC somehow.

Logs related to the SABM issue (ERROR IND):

20201019124504787 DLLAPD <0011> lapd_core.c:909 ((bts=0,trx=0,ts=0,ss=0)[DCCH][0]) SABM not allowed during contention resolution (state=LAPD_STATE_TIMER_RECOV)
20201019124504787 DLLAPD <0011> lapd_core.c:426 ((bts=0,trx=0,ts=0,ss=0)[DCCH][0]) sending MDL-ERROR-IND cause 14 from state LAPD_STATE_TIMER_RECOV
20201019124504787 DLLAPD <0011> lapdm.c:550 ((bts=0,trx=0,ts=0,ss=0)[DCCH][0]) sending MDL-ERROR-IND 14
20201019124504787 DRSL <0000> rsl.c:3003 (bts=0,trx=0,ts=0,ss=0) Fwd RLL msg ERROR_IND from LAPDm to A-bis

And the lapdm uplink "Assignment failure" seems to be not forwarded due to:

20201019124505022 DLLAPD <0011> lapd_core.c:1506 ((bts=0,trx=0,ts=0,ss=0)[DCCH][0]) N(S) sequence error: N(S)=0, V(R)=2 (state LAPD_STATE_TIMER_RECOV)

pespin wrote:

A bit before the "BSSMAP Assignemtn Failure" being sent BSC->MSC for the MT leg of the preemptive emergency call, I see 2 suspcious things:

• BTS sending an "ERROR INDication" to BSC with cause: "Cause: SABM frame with information not allowed in this state (14)".

• PCAP file packet 3659: This SABM is received on the TS0/sdcch-0.
• If you use the wireshark-mate rules from git.osmocom.org/wireshark-mate.git, this will be mate.rsl_lchan == 6
  • channel activated in 1327
  • CM service request for MO call in 1338
  • CC SETUP for MO call in 1371
  • SACCH deactivated in 1440
  • RF CHAN REL in 1566 + ACK in 1569

So as the lchan is deactivated, why do we get a SABM fram in uplink on that lchan 48 seconds later in 3595?

Ok, nevermind. The same SDCCH-0 gets re-cycled is "mate.rsl_lchan == 17" in 3517.

• 3521: CHAN ACT ACK
• 3532: PAGING RESP
• 3545: CC SETUP
• 3579: CC CALL CONF
• 3595: RR ASSIGNMENT CMD
• 3619: RR ASSIGNMENT CMD on Um
• 3647: RR ASSIGNMENT CMD on Um (retransmission)
• 3659: LAPDM SABM frame in uplink on that same lchan

So it looks like the MS should be establishing LAPDm on the new TCH/F, but somehow tries it on the old channel?

To be correct, there also seems to be a bug on our side: As the contention resolution procedure has happened already at the start of the lchan in 3531/3547, it is actually legal for the MS to do a SABM at a later point in time, without any information field. This could be seen as a "re-start/re-set the connection".

3GPP TS 44.006 8.4.2.1

If an SABM command is received while in the multiple-frame-established state, the data link layer entity shall proceed as follows:

• if the SABM command carries no information field (i.e. L=0), then the data link layer entity shall conform to the re-establishment procedure described in sub-clause 8.6;

So we are clarly not doing that.

3GPP TS 48.006 Section 8.6.3: Procedures for re-establishment

When the data link layer receives in the multiple frame established state or timer recovery state a DL-ESTABLISH-REQUEST primitive from layer 3 or an SABM (with L=0), the normal establishment procedure of sub-clause 8.4.1.2 shall be initiated. Any information frames in the I queue (including I frames for DL-DATA-REQUEST primitives and any received segmented layer 3 message units for which the last segment has not been received) shall be discarded.

• 3666 is the UA in response to the SABM
• 3674 is the ASSIGNMENT FAILURE on L3 inside the re-established LAPDm

So all that seems broken here is that osmo-bts sends a RLL ERR IND even though it proceeds.

The assignment fiilure states "protocol error, unspecified" - which is of course not helpful.

I will give a try again to the osmo-gsm-tester preemption emergency call after this patch is merged:
https://gerrit.osmocom.org/c/libosmocore/+/20807

After that, I expect to see the Assignment Failure sent by the MS to be forwarded fine towards the BSC by the BTS.

The test most probably will still fail due to the Assignment Failure sent by the MS, probably because it doesn't support voicecalls (or we do something wrong?). Once we have more SierraW modems (4 of them) I'll test again and I expect to see the test passing reliably.

I tested again with that fix applied, but still it's ending up int oan unrelated problem (which is kind of expectable):
During the 2nd (preemptive) call, MO establishment goes fines, and MT is paged fine (through SDCCH), but then when BSC has to assign a TCH from MSC's Assignment Request, it will fail with Assignment Failure "No radio resources available", which is expected to happen sometimes since the older TCH may have not time to become released properly.

• Have the emergency MT mobile camping on a different BTS with enough TCH (not sure how to properly tell a specific MS to register to one BTS and not to another, plus I need to make sure I can run several BTSs in osmo-gsm-tester in one test, which we didn't do so far).
• Have the emergency number listening on MNCC (which means I need to either implement some MNCC emulator in osmo-gsm-tester, or add support for osmo-sip-connector + pbx in osmo-gsm-tester).

In any case, the preemption to give pass to an emerency call seems to be working fine with real modems.

To make it pass quickly I could simply check in the test that:
1- One of the 2 modems calls is released: "/sierra_6: DBG: 'org.ofono.VoiceCallManager'.CallRemoved() > /sierra_6/voicecall01"
2 the state of the MO emergency modem can get to state "alerting" before being rejected (maybe difficult since we do polling):

16:56:38.753298 tst  emergency_preemptive_call.py:81: dialing Emergency Number 112
16:56:39.002665 tst                          /gobi_1: DBG: Dialing: 112
16:56:39.180053 tst                          /gobi_1: DBG: Adding /gobi_1/voicecall01 to call list
16:56:39.282520 tst                          /gobi_2: DBG: Waiting for incoming call from: 2613
16:56:39.376558 bus                          /gobi_1: DBG: 'org.ofono.Modem'.PropertyChanged() -> Emergency=True
16:56:39.468399 tst                          /gobi_1: DBG: 'org.ofono.VoiceCallManager'.CallAdded() -> /gobi_1/voicecall01="{'Name': '', 'RemoteMultiparty': False, 'LineIdentification': '112', 'Multiparty': False, 'RemoteHeld': False, 'Emergency': True, 'State': 'dialing'}" 
16:56:39.558329 tst                          /gobi_1: DBG: Call already exists '/gobi_1/voicecall01'
16:56:40.300973 tst              /gobi_1/voicecall01: DBG: '/gobi_1/voicecall01':'org.ofono.VoiceCall'.PropertyChanged() -> State=alerting
16:56:40.652034 tst            /sierra_6/voicecall01: DBG: '/sierra_6/voicecall01':'org.ofono.VoiceCall'.PropertyChanged() -> State=disconnected
16:56:40.753789 tst                        /sierra_6: DBG: 'org.ofono.VoiceCallManager'.CallRemoved() -> /sierra_6/voicecall01
16:56:42.385690 tst                          /gobi_2: DBG: 'org.ofono.VoiceCallManager'.CallAdded() -> /gobi_2/voicecall01="{'Name': '', 'RemoteMultiparty': False, 'LineIdentification': '2613', 'Multiparty': False, 'RemoteHeld': False, 'Emergency': False, 'State': 'dialing'}" 
16:56:43.087680 tst              /gobi_2/voicecall01: DBG: '/gobi_2/voicecall01':'org.ofono.VoiceCall'.PropertyChanged() -> State=disconnected
16:56:43.179915 tst                          /gobi_2: DBG: 'org.ofono.VoiceCallManager'.CallRemoved() -> /gobi_2/voicecall01
16:56:56.972652 tst                        /sierra_6: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Status=searching
16:56:57.073310 tst                        /sierra_6: DBG: 'org.ofono.NetworkRegistration'.PropertyChanged() -> Name=
16:57:10.318428 bus                          /gobi_1: DBG: 'org.ofono.Modem'.PropertyChanged() -> Emergency=False
16:57:10.402074 tst              /gobi_1/voicecall01: DBG: '/gobi_1/voicecall01':'org.ofono.VoiceCall'.PropertyChanged() -> State=disconnected
16:57:10.481582 tst                          /gobi_1: DBG: 'org.ofono.VoiceCallManager'.CallRemoved() -> /gobi_1/voicecall01

I confirm the LAPDm issue is fixed now (the test only runs into that situation somatimes, when the previous call happens to be released before the 2nd MT Assignment Release).

Test is passing so far reliably by relaxing a bit the expectancies while still testing important preemption side (regular emergency call fwd is tested in a separate test):
https://gerrit.osmocom.org/c/osmo-gsm-tester/+/20825 sysmocom: emergency_preemptive_call.py: Avoid test failure if 2nd call not ...

Assigning ticket to dexter for him to look at the duplicated BSSMAP Clear Request BSC->MSC