Cellular Network Infrastructure » Core Network (CN) » OsmoMSC

The network advertises R99 capability; the phone is a S4mini, so definitely UMTS capable. Classmark 2 is optional, but supposedly to be sent for UMTS capable networks. It's interesting to note this, but it's a valid situation and OsmoMSC should certainly not crash.

See attached pcap with gsmtap showing R99 in SI3 and successful auth response leading to the crash (gsmtap_log included)

OsmoMSC log & bt:

Thu Feb 15 21:38:59 2018 DRLL DEBUG gsm_04_08.c:3462 Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Thu Feb 15 21:38:59 2018 DMM DEBUG gsm_04_08.c:982 IMSI:901700000014701: MM R99 AUTHENTICATION RESPONSE (res = a2764a1cfe5f6c2d)
Thu Feb 15 21:38:59 2018 DVLR DEBUG vlr.c:1088 VLR_Authenticate(901700000014701)[0x555555939fb0]{VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Thu Feb 15 21:38:59 2018 DVLR DEBUG vlr_auth_fsm.c:142 SUBSCR(IMSI:901700000014701) received res: a2 76 4a 1c fe 5f 6c 2d 
Thu Feb 15 21:38:59 2018 DVLR INFO vlr_auth_fsm.c:179 SUBSCR(IMSI:901700000014701) AUTH established UMTS security context
Thu Feb 15 21:38:59 2018 DVLR DEBUG vlr_auth_fsm.c:224 VLR_Authenticate(901700000014701)[0x555555939fb0]{VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
Thu Feb 15 21:38:59 2018 DVLR DEBUG vlr_auth_fsm.c:228 VLR_Authenticate(901700000014701)[0x555555939fb0]{VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
Thu Feb 15 21:38:59 2018 DVLR DEBUG vlr_auth_fsm.c:233 VLR_Authenticate(901700000014701)[0x555555939fb0]{VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Thu Feb 15 21:38:59 2018 DVLR DEBUG vlr_auth_fsm.c:233 VLR_Authenticate(901700000014701)[0x555555939fb0]{VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000014701)[0x55555594dd70]
Thu Feb 15 21:38:59 2018 DVLR DEBUG vlr_auth_fsm.c:233 VLR_Authenticate(901700000014701)[0x555555939fb0]{VLR_SUB_AS_AUTHENTICATED}: Freeing instance
Thu Feb 15 21:38:59 2018 DVLR DEBUG fsm.c:318 VLR_Authenticate(901700000014701)[0x555555939fb0]{VLR_SUB_AS_AUTHENTICATED}: Deallocated
Thu Feb 15 21:38:59 2018 DVLR DEBUG vlr_auth_fsm.c:233 vlr_lu_fsm(901700000014701)[0x55555594dd70]{VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
Thu Feb 15 21:38:59 2018 DVLR DEBUG vlr_lu_fsm.c:822 vlr_lu_fsm(901700000014701)[0x55555594dd70]{VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Thu Feb 15 21:38:59 2018 DVLR DEBUG vlr.c:1123 vlr_lu_fsm(901700000014701)[0x55555594dd70]{VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Thu Feb 15 21:38:59 2018 DMM DEBUG gsm_04_08.c:3644 -> CIPHER MODE COMMAND IMSI:901700000014701
Thu Feb 15 21:38:59 2018 DMSC DEBUG gsm_04_08.c:120 CLASSMARK 2 unknown, assuming MS doesn't support A5/3
Thu Feb 15 21:38:59 2018 DMM ERROR gsm_04_08.c:3660 IMSI:901700000014701: cannot start ciphering, no intersection between MSC-configured and MS-supported A5 algorithms
Thu Feb 15 21:38:59 2018 DVLR ERROR vlr_lu_fsm.c:842 vlr_lu_fsm(901700000014701)[0x55555594dd70]{VLR_ULA_S_WAIT_AUTH}: Failed to send Ciphering Mode Command
Thu Feb 15 21:38:59 2018 DMM DEBUG msc_ifaces.c:118 -> CM SERVICE Reject cause: 17
Program received signal SIGSEGV, Segmentation fault.
vlr_subscr_name (vsub=0x3030303037313039) at ../../../../src/osmo-msc/src/libcommon/gsm_subscriber_base.c:46
46        if (vsub->msisdn[0])
(gdb) bt
#0  vlr_subscr_name (vsub=0x3030303037313039) at ../../../../src/osmo-msc/src/libcommon/gsm_subscriber_base.c:46
#1  0x000055555557285b in msc_tx (conn=0x55555594dfc0, msg=0x55555594d480) at ../../../../src/osmo-msc/src/libmsc/msc_ifaces.c:51
#2  0x0000555555584841 in vlr_lu_compl_fsm_failure (fi=0x55555594dd70, cause=<optimized out>) at ../../../../src/osmo-msc/src/libvlr/vlr_lu_fsm.c:350
#3  0x00007ffff7333e7f in _osmo_fsm_inst_dispatch (fi=0x55555594dd70, event=3, event@entry=21845, data=data@entry=0x7fffffffdf5c, 
    file=file@entry=0x5555555971e0 "../../../../src/osmo-msc/src/libvlr/vlr_auth_fsm.c", line=line@entry=233) at ../../../src/libosmocore/src/fsm.c:481
#4  0x00007ffff733444a in _osmo_fsm_inst_term (fi=fi@entry=0x555555939fb0, cause=cause@entry=OSMO_FSM_TERM_REGULAR, data=data@entry=0x7fffffffdf5c, 
    file=file@entry=0x5555555971e0 "../../../../src/osmo-msc/src/libvlr/vlr_auth_fsm.c", line=line@entry=233) at ../../../src/libosmocore/src/fsm.c:534
#5  0x0000555555583f83 in auth_fsm_term (fi=0x555555939fb0, res=<optimized out>) at ../../../../src/osmo-msc/src/libvlr/vlr_auth_fsm.c:233
#6  0x00007ffff7333e7f in _osmo_fsm_inst_dispatch (fi=0x555555939fb0, event=event@entry=4, data=data@entry=0x7fffffffdff0, file=file@entry=0x555555596370 "../../../../src/osmo-msc/src/libvlr/vlr.c", 
    line=line@entry=1088) at ../../../src/libosmocore/src/fsm.c:481
#7  0x000055555558210b in vlr_subscr_rx_auth_resp (vsub=<optimized out>, is_r99=is_r99@entry=true, is_utran=<optimized out>, res=res@entry=0x7fffffffe040 "\242vJ\034\376_l-j", res_len=res_len@entry=8 '\b')
    at ../../../../src/osmo-msc/src/libvlr/vlr.c:1088
#8  0x000055555556ce2e in gsm48_rx_mm_auth_resp (msg=0x555555943420, conn=0x555555943420) at ../../../../src/osmo-msc/src/libmsc/gsm_04_08.c:984
#9  gsm0408_rcv_mm (msg=0x555555943420, conn=0x555555943420) at ../../../../src/osmo-msc/src/libmsc/gsm_04_08.c:1112
#10 gsm0408_dispatch (conn=conn@entry=0x555555943420, msg=msg@entry=0x55555593a200) at ../../../../src/osmo-msc/src/libmsc/gsm_04_08.c:3493
#11 0x00005555555794ad in msc_dtap (conn=0x555555943420, link_id=<optimized out>, msg=0x55555593a200) at ../../../../src/osmo-msc/src/libmsc/osmo_msc.c:107
#12 0x0000555555562d74 in rx_dtap (scu=0x7ffff754a900 <hexd_buff>, a_conn_info=0x7fffffffe0c0, a_conn_info=0x7fffffffe0c0, msg=<optimized out>) at ../../../../src/osmo-msc/src/libmsc/a_iface_bssap.c:600
#13 a_sccp_rx_dt (scu=scu@entry=0x5555558ea700, a_conn_info=a_conn_info@entry=0x7fffffffe0f0, msg=<optimized out>) at ../../../../src/osmo-msc/src/libmsc/a_iface_bssap.c:622
#14 0x0000555555560f24 in sccp_sap_up (oph=0x55555593a288, _scu=0x5555558ea700) at ../../../../src/osmo-msc/src/libmsc/a_iface.c:553
#15 0x00007ffff7333e7f in _osmo_fsm_inst_dispatch (fi=0x5555558f0ed0, event=11, data=data@entry=0x555555942f30, file=file@entry=0x7ffff6cb14a8 "../../../src/libosmo-sccp/src/sccp_scoc.c", line=line@entry=1581)
    at ../../../src/libosmocore/src/fsm.c:481
#16 0x00007ffff6ca1985 in sccp_scoc_rx_from_scrc (inst=inst@entry=0x5555558e8150, xua=xua@entry=0x555555942f30) at ../../../src/libosmo-sccp/src/sccp_scoc.c:1581
#17 0x00007ffff6c9f67b in scrc_rx_mtp_xfer_ind_xua (inst=inst@entry=0x5555558e8150, xua=0x555555942f30) at ../../../src/libosmo-sccp/src/sccp_scrc.c:449
#18 0x00007ffff6ca2555 in mtp_user_prim_cb (oph=0x555555931da8, ctx=0x5555558e8150) at ../../../src/libosmo-sccp/src/sccp_user.c:176
#19 0x00007ffff6c9a393 in m3ua_rx_xfer (xua=0x5555558f36b0, asp=0x5555558c0550) at ../../../src/libosmo-sccp/src/m3ua.c:586
#20 m3ua_rx_msg (asp=asp@entry=0x5555558c0550, msg=msg@entry=0x55555592dc10) at ../../../src/libosmo-sccp/src/m3ua.c:738
#21 0x00007ffff6ca5553 in xua_cli_read_cb (conn=<optimized out>) at ../../../src/libosmo-sccp/src/osmo_ss7.c:1592
#22 0x00007ffff55bf3fb in osmo_stream_cli_read (cli=0x5555558e59a0) at ../../../src/libosmo-netif/src/stream.c:192
#23 osmo_stream_cli_fd_cb (ofd=<optimized out>, what=1) at ../../../src/libosmo-netif/src/stream.c:276
#24 0x00007ffff7330a71 in osmo_fd_disp_fds (_eset=0x7fffffffe500, _wset=0x7fffffffe480, _rset=0x7fffffffe400) at ../../../src/libosmocore/src/select.c:216
#25 osmo_select_main (polling=<optimized out>) at ../../../src/libosmocore/src/select.c:256
#26 0x000055555555f46c in main (argc=1, argv=<optimized out>) at ../../../../src/osmo-msc/src/osmo-msc/msc_main.c:533

We don't send a Classmark Inquiry and might not even allow Classmark Change to be received (I think I dimly remember such factoid).
So your suggestions make perfect sense.

Please make sure to add a ttcn3 testcase before fixing this

In osmo-ttcn3-hacks/msc, we have a test that is very similar to the described situation: TC_lu_imsi_auth_tmsi_encr_3_1().
In fact all that is needed to trigger above segfault is to enable debug log for the 'msc' category!
i.e. a workaround for this issue is to disable debug logging for the 'msc' category ; )

About CM2: that test does send a classmark update containing CM2, to indicate that A5/3 is not supported.
The scenario described above demands that CM2 should not be known, and we should probably have a separate test for that scenario, however, CM2 presence does not influence triggering of the segfault; all that is needed is the decision that no supported cipher is available combined with 'msc' log on 'debug'.

submitting the ttcn3 test is on the way...

https://gerrit.osmocom.org/7050

I found the bug, and it's a hard to spot one. Quiz question, what's wrong in this function:

/* 4.1.2.1 after Authentication successful (or no auth rqd) */
static void vlr_loc_upd_post_auth(struct osmo_fsm_inst *fi)
{
        struct lu_fsm_priv *lfp = fi->priv;
        struct vlr_subscr *vsub = lfp->vsub;

        LOGPFSM(fi, "%s()\n", __func__);

        OSMO_ASSERT(vsub);

        if (!is_ciph_required(lfp)) {
                vlr_loc_upd_post_ciph(fi);
                return;
        }

        if (!vsub->last_tuple) {
                LOGPFSML(fi, LOGL_ERROR, "No auth tuple available\n");
                vlr_lu_compl_fsm_failure(fi, GSM48_REJECT_NETWORK_FAILURE);
                return;
        }

        if (vlr_set_ciph_mode(vsub->vlr, fi, lfp->msc_conn_ref,
                              lfp->ciphering_required,
                              vlr_use_umts_aka(&vsub->last_tuple->vec, lfp->is_r99),
                              vsub->vlr->cfg.retrieve_imeisv_ciphered)) {
                LOGPFSML(fi, LOGL_ERROR,
                         "Failed to send Ciphering Mode Command\n");
                vlr_lu_compl_fsm_failure(fi, GSM48_REJECT_NETWORK_FAILURE);
                return;
        }

        osmo_fsm_inst_state_chg(fi, VLR_ULA_S_WAIT_CIPH, LU_TIMEOUT_LONG, 0);
}

Submitting the patch now... Spoiler alert!

I must admit, to go and analyze the stack frame, I did go back to msc_vlr_tests to reproduce the issue and be able to trigger the bug without waiting for the ttcn3 suite to get going every time. So we now have a ttcn3 test (MSC_Tests.TC_lu_imsi_auth_tmsi_encr_3_1_log_msc_debug in https://gerrit.osmocom.org/7050) and an msc_vlr_test (msc_vlr_test_gsm_ciph:test_a5_3_not_supported(), patch submission pending) against this failure.

https://gerrit.osmocom.org/7055 <-- fix

it's about time this issue got resolved. merged a month ago.

upon fixing the segfault, I forgot to track the part of sending a Classmark Request. Will do so now in #3043.