[PATCH] osmo-msc[master]: msc_vlr_test_gsm_ciph: add test for GSM AKA in UMTS environment

This is merely a historical archive of years 2008-2021, before the migration to mailman3.

A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/gerrit-log@lists.osmocom.org/.

Neels Hofmeyr gerrit-no-reply at lists.osmocom.org
Sat Mar 10 03:41:32 UTC 2018


msc_vlr_test_gsm_ciph: add test for GSM AKA in UMTS environment

Even on an R99 capable MS with a UMTS AKA capable USIM, the MS may still choose
to only perform GSM AKA, as long as the bearer is GERAN. In that case, we must
make sure to send the GSM AKA Kc for ciphering.

Add test_gsm_ciph_in_umts_env() to msc_vlr_test_gsm_ciph.c to answer an Auth
Request with a GSM AKA response (see the log stating "AUTH established GSM
security context" after we sent a UMTS AKA challenge).

In the test, show that we currently send the *wrong* Kc, i.e. the UMTS AKA
derived Kc for GERAN, instead of the correct Kc for GSM AKA (which was received
from the HLR in the auth tuples).

Subsequent patch I42ce51ae979f42d173a45ae69273071c426bf97c will fix this and
correct the test expectations.

Related: OS#2793
Change-Id: I85f12a20dcd701e671188e56811ec7b58d84da82
---
M tests/msc_vlr/msc_vlr_test_gsm_ciph.c
M tests/msc_vlr/msc_vlr_test_gsm_ciph.err
2 files changed, 725 insertions(+), 0 deletions(-)


  git pull ssh://gerrit.osmocom.org:29418/osmo-msc refs/changes/86/7186/2

diff --git a/tests/msc_vlr/msc_vlr_test_gsm_ciph.c b/tests/msc_vlr/msc_vlr_test_gsm_ciph.c
index 1e6bf7c..d8c0441 100644
--- a/tests/msc_vlr/msc_vlr_test_gsm_ciph.c
+++ b/tests/msc_vlr/msc_vlr_test_gsm_ciph.c
@@ -794,11 +794,271 @@
 	comment_end();
 }
 
+static void test_gsm_ciph_in_umts_env()
+{
+	struct vlr_subscr *vsub;
+	const char *imsi = "901700000010650";
+	const char *sms =
+		"09" /* SMS messages */
+		"01" /* CP-DATA */
+		"58" /* length */
+		"01" /* Network to MS */
+		"00" /* reference */
+		/* originator (gsm411_send_sms() hardcodes this weird nr) */
+		"0791" "447758100650" /* 447785016005 */
+		"00" /* dest */
+		/* SMS TPDU */
+		"4c" /* len */
+		"00" /* SMS deliver */
+		"05802443f2" /* originating address 42342 */
+		"00" /* TP-PID */
+		"00" /* GSM default alphabet */
+		"071010" /* Y-M-D (from wrapped gsm340_gen_scts())*/
+		"000000" /* H-M-S */
+		"00" /* GMT+0 */
+		"44" /* data length */
+		"5079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0e"
+		"d3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb"
+		"0c7ac3e9e9b7db05";
+
+	comment_start();
+
+	/* implicit: net->authentication_required = true; */
+	net->a5_encryption_mask = (1 << 1);
+	rx_from_ran = RAN_GERAN_A;
+
+	btw("Location Update request causes a GSUP Send Auth Info request to HLR");
+	lu_result_sent = RES_NONE;
+	gsup_expect_tx("080108" "09710000000156f0");
+	ms_sends_msg("0508" /* MM LU */
+		     "7" /* ciph key seq: no key available */
+		     "0" /* LU type: normal */
+		     "ffffff" "0000" /* LAI, LAC */
+		     "57" /* classmark 1: R99, early classmark, no power lvl */
+		     "089910070000106005" /* IMSI */
+		     "3303575886" /* classmark 2 */
+		     );
+	OSMO_ASSERT(gsup_tx_confirmed);
+	VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+	btw("from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends *UMTS AKA* Auth Req to MS");
+	/* based on
+	 * 2G auth: COMP128v1
+	 *          KI=7bcd108be4c3d551ee6c67faaf52bd68
+	 * 3G auth: MILENAGE
+	 *          K=7bcd108be4c3d551ee6c67faaf52bd68
+	 *          OPC=6e23f641ce724679b73d933515a8589d
+	 *          IND-bitlen=5 last-SQN=641
+	 * Note that the SRES will be calculated by COMP128v1, separately from 3G tokens;
+	 * the resulting Kc to use for ciphering returned by the HLR is also calculated from COMP128v1.
+	 */
+	auth_request_sent = false;
+	auth_request_expect_rand = "4ac8d1cd1a51937597ca1016fe69a0fa";
+	auth_request_expect_autn = "2d837d2b0d6f00004b282d5acf23428d";
+	gsup_rx("0a"
+		/* imsi */
+		"0108" "09710000000156f0"
+		/* 5 auth vectors... */
+		/* TL    TL     rand */
+		"0362" "2010" "4ac8d1cd1a51937597ca1016fe69a0fa"
+		/*       TL     sres       TL     kc */
+		       "2104" "dacc4b26" "2208" "7a75f0ac9b844400"
+		/*       TL     3G IK */
+		       "2310" "3747da4e31545baa2db59e500bdae047"
+		/*       TL     3G CK */
+		       "2410" "8544d35b945ccba01a7f1293575291c3"
+		/*       TL     AUTN */
+		       "2510" "2d837d2b0d6f00004b282d5acf23428d"
+		/*       TL     RES */
+		       "2708" "37527064741f8ddb"
+		/* TL    TL     rand */
+		"0362" "2010" "b2661531b97b12c5a2edc21a0ed16fc5"
+		       "2104" "2fb4cfad" "2208" "da149b11d473f400"
+		       "2310" "3fe013b1a428ea737c37f8f0288c8edf"
+		       "2410" "f275438c02b97e4d6f639dddda3d10b9"
+		       "2510" "78cdd96c60840000322f421b3bb778b1"
+		       "2708" "ed3ebf9cb6ea48ed"
+		"0362" "2010" "54d8f19778056666b41c8c25e52eb60c"
+		       "2104" "0ff61e0f" "2208" "26ec67fad3073000"
+		       "2310" "2868b0922c652616f1c975e3eaf7943a"
+		       "2410" "6a84a20b1bc13ec9840466406d2dd91e"
+		       "2510" "53f3e5632b3d00008865dd54d49663f2"
+		       "2708" "86e848a9e7ad8cd5"
+		"0362" "2010" "1f05607ff9c8984f46ad97f8c9a94982"
+		       "2104" "91a36e3d" "2208" "5d84421884fdcc00"
+		       "2310" "2171fef54b81e30c83a598a5e44f634c"
+		       "2410" "f02d088697509827565b46938fece211"
+		       "2510" "1b43bbf9815e00001cb9b2a9f6b8a77c"
+		       "2708" "373e67d62e719c51"
+		"0362" "2010" "80d89a58a2a41050918caf68a4e93c64"
+		       "2104" "a319f5f1" "2208" "883df2b867293000"
+		       "2310" "fa5d70f929ff298efb160413698dc107"
+		       "2410" "ae9a3d8ce70ce13bac297bdb91cd6c68"
+		       "2510" "5c0dc2eeaefa0000396882a1fe2cf80b"
+		       "2708" "65ab1cad216bfe87",
+		NULL);
+	VERBOSE_ASSERT(auth_request_sent, == true, "%d");
+	VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+	btw("MS sends *GSM AKA* Authen Response, VLR accepts and sends Ciphering Mode Command to MS");
+	/* EXPECTING ERROR: should be the GSM AKA kc:
+	expect_cipher_mode_cmd("7a75f0ac9b844400");
+	 * but instead is the UMTS AKA derived kc: */
+	expect_cipher_mode_cmd("85c985d6f980e18e");
+	ms_sends_msg("0554" "dacc4b26");
+	OSMO_ASSERT(cipher_mode_cmd_sent);
+	VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+	btw("MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR");
+	gsup_expect_tx("04010809710000000156f0");
+	ms_sends_msg("0632");
+	VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+	btw("HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT");
+	gsup_rx("10010809710000000156f00804032443f2",
+		"12010809710000000156f0");
+	VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+	btw("HLR also sends GSUP _UPDATE_LOCATION_RESULT");
+	expect_bssap_clear();
+	gsup_rx("06010809710000000156f0", NULL);
+	VERBOSE_ASSERT(bssap_clear_sent, == true, "%d");
+
+	btw("LU was successful, and the conn has already been closed");
+	VERBOSE_ASSERT(lu_result_sent, == RES_ACCEPT, "%d");
+	EXPECT_CONN_COUNT(0);
+
+	BTW("after a while, a new conn sends a CM Service Request. VLR responds with *UMTS AKA* Auth Req, 2nd auth vector");
+	auth_request_sent = false;
+	auth_request_expect_rand = "b2661531b97b12c5a2edc21a0ed16fc5";
+	auth_request_expect_autn = "78cdd96c60840000322f421b3bb778b1";
+	cm_service_result_sent = RES_NONE;
+	ms_sends_msg("052478"
+		     "03575886" /* classmark 2 */
+		     "089910070000106005" /* IMSI */);
+	OSMO_ASSERT(g_conn);
+	OSMO_ASSERT(g_conn->conn_fsm);
+	OSMO_ASSERT(g_conn->vsub);
+	VERBOSE_ASSERT(cm_service_result_sent, == RES_NONE, "%d");
+	VERBOSE_ASSERT(auth_request_sent, == true, "%d");
+
+	btw("needs auth, not yet accepted");
+	EXPECT_ACCEPTED(false);
+	thwart_rx_non_initial_requests();
+
+	btw("MS sends *GSM AKA* Authen Response, VLR accepts and requests Ciphering");
+	/* EXPECTING ERROR: should be the GSM AKA kc:
+	expect_cipher_mode_cmd("da149b11d473f400");
+	 * but instead is the UMTS AKA derived kc: */
+	expect_cipher_mode_cmd("dec1351054200a58");
+	ms_sends_msg("0554" "2fb4cfad");
+	VERBOSE_ASSERT(cm_service_result_sent, == RES_NONE, "%d");
+	VERBOSE_ASSERT(cipher_mode_cmd_sent, == true, "%d");
+
+	btw("MS sends Ciphering Mode Complete, VLR accepts; above Ciphering is an implicit CM Service Accept");
+	ms_sends_msg("0632");
+	VERBOSE_ASSERT(cm_service_result_sent, == RES_NONE, "%d");
+
+	btw("a USSD request is serviced");
+	dtap_expect_tx_ussd("Your extension is 42342\r");
+	expect_bssap_clear();
+	ms_sends_msg("0b3b1c15a11302010002013b300b04010f0406aa510c061b017f0100");
+	OSMO_ASSERT(dtap_tx_confirmed);
+	VERBOSE_ASSERT(bssap_clear_sent, == true, "%d");
+
+	btw("all requests serviced, conn has been released");
+	EXPECT_CONN_COUNT(0);
+
+	BTW("an SMS is sent, MS is paged");
+	paging_expect_imsi(imsi);
+	paging_sent = false;
+	vsub = vlr_subscr_find_by_imsi(net->vlr, imsi);
+	OSMO_ASSERT(vsub);
+	VERBOSE_ASSERT(llist_count(&vsub->cs.requests), == 0, "%d");
+
+	send_sms(vsub, vsub,
+		 "Privacy in residential applications is a desirable"
+		 " marketing option.");
+
+	VERBOSE_ASSERT(llist_count(&vsub->cs.requests), == 1, "%d");
+	vlr_subscr_put(vsub);
+	vsub = NULL;
+	VERBOSE_ASSERT(paging_sent, == true, "%d");
+	VERBOSE_ASSERT(paging_stopped, == false, "%d");
+
+	btw("the subscriber and its pending request should remain");
+	vsub = vlr_subscr_find_by_imsi(net->vlr, imsi);
+	OSMO_ASSERT(vsub);
+	VERBOSE_ASSERT(llist_count(&vsub->cs.requests), == 1, "%d");
+	vlr_subscr_put(vsub);
+
+	btw("MS replies with Paging Response, and VLR sends *UMTS AKA* Auth Request with third key");
+	auth_request_sent = false;
+	auth_request_expect_rand = "54d8f19778056666b41c8c25e52eb60c";
+	auth_request_expect_autn = "53f3e5632b3d00008865dd54d49663f2";
+	ms_sends_msg("062707"
+		     "03575886" /* classmark 2 */
+		     "089910070000106005" /* IMSI */);
+	VERBOSE_ASSERT(auth_request_sent, == true, "%d");
+
+	btw("needs auth, not yet accepted");
+	EXPECT_ACCEPTED(false);
+	thwart_rx_non_initial_requests();
+
+	btw("MS sends *GSM AKA* Authen Response, VLR accepts and requests Ciphering");
+	/* EXPECTING ERROR: should be the GSM AKA kc:
+	expect_cipher_mode_cmd("26ec67fad3073000");
+	 * but instead is the UMTS AKA derived kc: */
+	expect_cipher_mode_cmd("3721013ab07e55fb");
+	ms_sends_msg("0554" "0ff61e0f");
+	VERBOSE_ASSERT(cipher_mode_cmd_sent, == true, "%d");
+
+	btw("MS sends Ciphering Mode Complete, VLR accepts and sends pending SMS");
+	dtap_expect_tx(sms);
+	ms_sends_msg("0632");
+	VERBOSE_ASSERT(dtap_tx_confirmed, == true, "%d");
+	VERBOSE_ASSERT(paging_stopped, == true, "%d");
+
+	btw("SMS was delivered, no requests pending for subscr");
+	vsub = vlr_subscr_find_by_imsi(net->vlr, imsi);
+	OSMO_ASSERT(vsub);
+	VERBOSE_ASSERT(llist_count(&vsub->cs.requests), == 0, "%d");
+	vlr_subscr_put(vsub);
+
+	btw("conn is still open to wait for SMS ack dance");
+	EXPECT_CONN_COUNT(1);
+
+	btw("MS replies with CP-ACK for received SMS");
+	ms_sends_msg("8904");
+	EXPECT_CONN_COUNT(1);
+
+	btw("MS also sends RP-ACK, MSC in turn sends CP-ACK for that");
+	dtap_expect_tx("0904");
+	expect_bssap_clear();
+	ms_sends_msg("890106020041020000");
+	VERBOSE_ASSERT(dtap_tx_confirmed, == true, "%d");
+	VERBOSE_ASSERT(bssap_clear_sent, == true, "%d");
+
+	btw("SMS is done, conn is gone");
+	EXPECT_CONN_COUNT(0);
+
+	BTW("subscriber detaches");
+	expect_bssap_clear();
+	ms_sends_msg("050130"
+		     "089910070000106005" /* IMSI */);
+	VERBOSE_ASSERT(bssap_clear_sent, == true, "%d");
+
+	EXPECT_CONN_COUNT(0);
+	clear_vlr();
+	comment_end();
+}
+
 msc_vlr_test_func_t msc_vlr_tests[] = {
 	test_ciph,
 	test_ciph_tmsi,
 	test_ciph_imei,
 	test_ciph_imeisv,
 	test_ciph_tmsi_imei,
+	test_gsm_ciph_in_umts_env,
 	NULL
 };
diff --git a/tests/msc_vlr/msc_vlr_test_gsm_ciph.err b/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
index 8f42d6e..196da8c 100644
--- a/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
+++ b/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
@@ -1719,6 +1719,471 @@
 full talloc report on 'msgb' (total      0 bytes in   1 blocks)
 talloc_total_blocks(tall_bsc_ctx) == 7
 
+===== test_gsm_ciph_in_umts_env
+- Location Update request causes a GSUP Send Auth Info request to HLR
+  MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
+  new conn
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
+DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
+DREF unknown: MSC conn use + fsm == 2 (0x5)
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
+DMM LU/new-LAC: 0/23
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth+Ciph
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
+DREF VLR subscr unknown usage increases to: 1
+DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
+DVLR New subscr, IMSI: 901700000010650
+DREF VLR subscr IMSI:901700000010650 usage increases to: 2
+DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
+DVLR GSUP tx: 08010809710000000156f0
+GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
+DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
+DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
+  lu_result_sent == 0
+- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends *UMTS AKA* Auth Req to MS
+<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f0036220104ac8d1cd1a51937597ca1016fe69a0fa2104dacc4b2622087a75f0ac9b84440023103747da4e31545baa2db59e500bdae04724108544d35b945ccba01a7f1293575291c325102d837d2b0d6f00004b282d5acf23428d270837527064741f8ddb03622010b2661531b97b12c5a2edc21a0ed16fc521042fb4cfad2208da149b11d473f40023103fe013b1a428ea737c37f8f0288c8edf2410f275438c02b97e4d6f639dddda3d10b9251078cdd96c60840000322f421b3bb778b12708ed3ebf9cb6ea48ed0362201054d8f19778056666b41c8c25e52eb60c21040ff61e0f220826ec67fad307300023102868b0922c652616f1c975e3eaf7943a24106a84a20b1bc13ec9840466406d2dd91e251053f3e5632b3d00008865dd54d49663f2270886e848a9e7ad8cd5036220101f05607ff9c8984f46ad97f8c9a94982210491a36e3d22085d84421884fdcc0023102171fef54b81e30c83a598a5e44f634c2410f02d088697509827565b46938fece21125101b43bbf9815e00001cb9b2a9f6b8a77c2708373e67d62e719c510362201080d89a58a2a41050918caf68a4e93c642104a319f5f12208883df2b8672930002310fa5d70f929ff298efb160413698dc1072410ae9a3d8ce70ce13bac297bdb91cd6c6825105c0dc2eeaefa0000396882a1fe2cf80b270865ab1cad216bfe87
+DVLR GSUP rx 511: 0a010809710000000156f0036220104ac8d1cd1a51937597ca1016fe69a0fa2104dacc4b2622087a75f0ac9b84440023103747da4e31545baa2db59e500bdae04724108544d35b945ccba01a7f1293575291c325102d837d2b0d6f00004b282d5acf23428d270837527064741f8ddb03622010b2661531b97b12c5a2edc21a0ed16fc521042fb4cfad2208da149b11d473f40023103fe013b1a428ea737c37f8f0288c8edf2410f275438c02b97e4d6f639dddda3d10b9251078cdd96c60840000322f421b3bb778b12708ed3ebf9cb6ea48ed0362201054d8f19778056666b41c8c25e52eb60c21040ff61e0f220826ec67fad307300023102868b0922c652616f1c975e3eaf7943a24106a84a20b1bc13ec9840466406d2dd91e251053f3e5632b3d00008865dd54d49663f2270886e848a9e7ad8cd5036220101f05607ff9c8984f46ad97f8c9a94982210491a36e3d22085d84421884fdcc0023102171fef54b81e30c83a598a5e44f634c2410f02d088697509827565b46938fece21125101b43bbf9815e00001cb9b2a9f6b8a77c2708373e67d62e719c510362201080d89a58a2a41050918caf68a4e93c642104a319f5f12208883df2b8672930002310fa5d70f929ff298efb160413698dc1072410ae9a3d8ce70ce13bac297bdb91cd6c6825105c0dc2eeaefa0000396882a1fe2cf80b270865ab1cad216bfe87
+DREF VLR subscr IMSI:901700000010650 usage increases to: 2
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
+DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
+- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
+- ...rand=4ac8d1cd1a51937597ca1016fe69a0fa
+- ...autn=2d837d2b0d6f00004b282d5acf23428d
+- ...expecting res=37527064741f8ddb
+DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
+<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
+  auth_request_sent == 1
+  lu_result_sent == 0
+- MS sends *GSM AKA* Authen Response, VLR accepts and sends Ciphering Mode Command to MS
+  MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
+DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
+DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
+DMM IMSI:901700000010650: MM GSM AUTHENTICATION RESPONSE (sres = dacc4b26)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
+DVLR SUBSCR(IMSI:901700000010650) received res: da cc 4b 26 
+DVLR SUBSCR(IMSI:901700000010650) AUTH established GSM security context
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
+DMM -> CIPHER MODE COMMAND IMSI:901700000010650
+- sending Ciphering Mode Command for IMSI:901700000010650: include_imeisv=0
+- ...perm algo: 2
+- ...key: 85c985d6f980e18e
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
+DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
+DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
+  lu_result_sent == 0
+- MS sends Ciphering Mode Complete, VLR accepts and sends GSUP LU Req to HLR
+  MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
+DRR IMSI:901700000010650: CIPHERING MODE COMPLETE
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
+DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
+DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
+DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
+DVLR GSUP tx: 04010809710000000156f0
+GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
+DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
+  lu_result_sent == 0
+- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
+<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
+DVLR GSUP rx 17: 10010809710000000156f00804032443f2
+DREF VLR subscr IMSI:901700000010650 usage increases to: 2
+DVLR IMSI:901700000010650 has MSISDN:42342
+DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
+DVLR GSUP tx: 12010809710000000156f0
+GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
+DREF VLR subscr MSISDN:42342 usage decreases to: 1
+<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
+  lu_result_sent == 0
+- HLR also sends GSUP _UPDATE_LOCATION_RESULT
+<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
+DVLR GSUP rx 11: 06010809710000000156f0
+DREF VLR subscr MSISDN:42342 usage increases to: 2
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
+DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
+DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
+DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
+DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
+DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
+DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
+DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
+DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
+DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
+DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
+DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
+DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
+DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
+DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
+DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
+DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
+DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
+- sending LU Accept for MSISDN:42342
+DREF VLR subscr MSISDN:42342 usage increases to: 3
+DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
+DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
+DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
+DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
+DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
+DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
+- BSSAP Clear --RAN_GERAN_A--> MS
+DREF MSISDN:42342: MSC conn use - fsm == 0 (0x0)
+DRLL subscr MSISDN:42342: Freeing subscriber connection
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
+DREF VLR subscr MSISDN:42342 usage decreases to: 1
+<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
+  bssap_clear_sent == 1
+- LU was successful, and the conn has already been closed
+  lu_result_sent == 1
+  llist_count(&net->subscr_conns) == 0
+---
+- after a while, a new conn sends a CM Service Request. VLR responds with *UMTS AKA* Auth Req, 2nd auth vector
+  MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
+  new conn
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
+DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
+DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
+DREF unknown: MSC conn use + fsm == 2 (0x5)
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth+Ciph
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
+DREF VLR subscr MSISDN:42342 usage increases to: 2
+DREF VLR subscr MSISDN:42342 usage increases to: 3
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
+- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
+- ...rand=b2661531b97b12c5a2edc21a0ed16fc5
+- ...autn=78cdd96c60840000322f421b3bb778b1
+- ...expecting res=ed3ebf9cb6ea48ed
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
+DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
+  cm_service_result_sent == 0
+  auth_request_sent == 1
+- needs auth, not yet accepted
+msc_subscr_conn_is_accepted() == false
+  requests shall be thwarted
+DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
+DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
+DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
+DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
+DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
+DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
+DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
+DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
+- MS sends *GSM AKA* Authen Response, VLR accepts and requests Ciphering
+  MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
+DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
+DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
+DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 2fb4cfad)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
+DVLR SUBSCR(MSISDN:42342) received res: 2f b4 cf ad 
+DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
+DMM -> CIPHER MODE COMMAND MSISDN:42342
+DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
+- sending Ciphering Mode Command for MSISDN:42342: include_imeisv=0
+- ...perm algo: 2
+- ...key: dec1351054200a58
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
+DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
+DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
+  cm_service_result_sent == 0
+  cipher_mode_cmd_sent == 1
+- MS sends Ciphering Mode Complete, VLR accepts; above Ciphering is an implicit CM Service Accept
+  MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
+DRR MSISDN:42342: CIPHERING MODE COMPLETE
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
+  cm_service_result_sent == 0
+- a USSD request is serviced
+  expecting USSD:
+  Your extension is 42342
+  MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
+DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
+DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
+DMM MSISDN:42342: rx msg NCSS:0x3b: received_cm_service_request changes to false
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
+DMM USSD: Own number requested
+DMM MSISDN:42342: MSISDN = 42342
+DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A
+- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
+- DTAP matches expected message
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
+DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
+- BSSAP Clear --RAN_GERAN_A--> MS
+DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
+DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
+DRLL subscr MSISDN:42342: Freeing subscriber connection
+DREF VLR subscr MSISDN:42342 usage decreases to: 1
+  bssap_clear_sent == 1
+- all requests serviced, conn has been released
+  llist_count(&net->subscr_conns) == 0
+---
+- an SMS is sent, MS is paged
+DREF VLR subscr MSISDN:42342 usage increases to: 2
+  llist_count(&vsub->cs.requests) == 0
+DREF VLR subscr MSISDN:42342 usage increases to: 3
+DMM Subscriber MSISDN:42342 not paged yet, start paging.
+  RAN_GERAN_A sends out paging request to IMSI 901700000010650, TMSI 0xffffffff, LAC 23
+  strcmp(paging_expecting_imsi, imsi) == 0
+DREF VLR subscr MSISDN:42342 usage increases to: 4
+  llist_count(&vsub->cs.requests) == 1
+DREF VLR subscr MSISDN:42342 usage decreases to: 3
+  paging_sent == 1
+  paging_stopped == 0
+- the subscriber and its pending request should remain
+DREF VLR subscr MSISDN:42342 usage increases to: 4
+  llist_count(&vsub->cs.requests) == 1
+DREF VLR subscr MSISDN:42342 usage decreases to: 3
+- MS replies with Paging Response, and VLR sends *UMTS AKA* Auth Request with third key
+  MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
+  new conn
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
+DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
+DRR PAGING RESPONSE: MI(IMSI)=901700000010650
+DREF unknown: MSC conn use + fsm == 2 (0x5)
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth+Ciph
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
+DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage increases to: 5
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2
+- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
+- ...rand=54d8f19778056666b41c8c25e52eb60c
+- ...autn=53f3e5632b3d00008865dd54d49663f2
+- ...expecting res=86e848a9e7ad8cd5
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
+DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
+DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
+  auth_request_sent == 1
+- needs auth, not yet accepted
+msc_subscr_conn_is_accepted() == false
+  requests shall be thwarted
+DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
+DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
+DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
+DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
+DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
+DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
+DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
+DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
+- MS sends *GSM AKA* Authen Response, VLR accepts and requests Ciphering
+  MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
+DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
+DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
+DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 0ff61e0f)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
+DVLR SUBSCR(MSISDN:42342) received res: 0f f6 1e 0f 
+DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
+DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
+DMM -> CIPHER MODE COMMAND MSISDN:42342
+DMSC CLASSMARK 1 unknown, assuming MS supports A5/1
+- sending Ciphering Mode Command for MSISDN:42342: include_imeisv=0
+- ...perm algo: 2
+- ...key: 3721013ab07e55fb
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
+DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
+DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
+  cipher_mode_cmd_sent == 1
+- MS sends Ciphering Mode Complete, VLR accepts and sends pending SMS
+  MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_CIPH_M_COMPL
+DRR MSISDN:42342: CIPHERING MODE COMPLETE
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DPAG Paging success for MSISDN:42342 (event=0)
+DPAG Calling paging cbfn.
+DREF VLR subscr MSISDN:42342 usage increases to: 5
+DREF MSISDN:42342: MSC conn use + trans_sms == 2 (0x14)
+DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
+- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
+- DTAP matches expected message
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: SMS
+  dtap_tx_confirmed == 1
+  paging_stopped == 1
+- SMS was delivered, no requests pending for subscr
+DREF VLR subscr MSISDN:42342 usage increases to: 5
+  llist_count(&vsub->cs.requests) == 0
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
+- conn is still open to wait for SMS ack dance
+  llist_count(&net->subscr_conns) == 1
+- MS replies with CP-ACK for received SMS
+  MSC <--RAN_GERAN_A-- MS: SMS:0x04
+DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
+DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: SMS
+DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
+  llist_count(&net->subscr_conns) == 1
+- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
+  MSC <--RAN_GERAN_A-- MS: SMS:0x01
+DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
+DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
+DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_GERAN_A
+- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
+- DTAP matches expected message
+DREF VLR subscr MSISDN:42342 usage decreases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+DREF MSISDN:42342: MSC conn use - trans_sms == 2 (0x6)
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
+DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
+DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
+- BSSAP Clear --RAN_GERAN_A--> MS
+DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
+DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
+DRLL subscr MSISDN:42342: Freeing subscriber connection
+DREF VLR subscr MSISDN:42342 usage decreases to: 1
+  dtap_tx_confirmed == 1
+  bssap_clear_sent == 1
+- SMS is done, conn is gone
+  llist_count(&net->subscr_conns) == 0
+---
+- subscriber detaches
+  MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
+  new conn
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
+DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
+DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
+DREF VLR subscr MSISDN:42342 usage increases to: 2
+DMM IMSI DETACH for MSISDN:42342
+DREF VLR subscr MSISDN:42342 usage decreases to: 1
+DREF VLR subscr MSISDN:42342 usage decreases to: 0
+DREF freeing VLR subscr MSISDN:42342
+DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
+- BSSAP Clear --RAN_GERAN_A--> MS
+DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
+DRLL Freeing subscriber connection with NULL subscriber
+  bssap_clear_sent == 1
+  llist_count(&net->subscr_conns) == 0
+===== test_gsm_ciph_in_umts_env: SUCCESS
+
+full talloc report on 'msgb' (total      0 bytes in   1 blocks)
+talloc_total_blocks(tall_bsc_ctx) == 7
+
 full talloc report on 'msgb' (total      0 bytes in   1 blocks)
 talloc_total_blocks(tall_bsc_ctx) == 7
 

-- 
To view, visit https://gerrit.osmocom.org/7186
To unsubscribe, visit https://gerrit.osmocom.org/settings

Gerrit-MessageType: newpatchset
Gerrit-Change-Id: I85f12a20dcd701e671188e56811ec7b58d84da82
Gerrit-PatchSet: 2
Gerrit-Project: osmo-msc
Gerrit-Branch: master
Gerrit-Owner: Neels Hofmeyr <nhofmeyr at sysmocom.de>
Gerrit-Reviewer: Jenkins Builder



More information about the gerrit-log mailing list