aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
Diffstat
-rw-r--r--include/osmocom/msc/a_iface.h2
-rw-r--r--include/osmocom/msc/gsm_data.h7
-rw-r--r--include/osmocom/msc/osmo_msc.h6
-rw-r--r--src/libmsc/a_iface.c10
-rw-r--r--src/libmsc/gsm_04_08.c134
-rw-r--r--src/libmsc/osmo_msc.c4
-rw-r--r--src/libmsc/subscr_conn.c74
-rw-r--r--tests/msc_vlr/Makefile.am1
-rw-r--r--tests/msc_vlr/msc_vlr_test_gsm_ciph.c403
-rw-r--r--tests/msc_vlr/msc_vlr_test_gsm_ciph.err925
-rw-r--r--tests/msc_vlr/msc_vlr_test_ms_timeout.c70
-rw-r--r--tests/msc_vlr/msc_vlr_test_ms_timeout.err130
-rw-r--r--tests/msc_vlr/msc_vlr_tests.c61
-rw-r--r--tests/msc_vlr/msc_vlr_tests.h1
14 files changed, 1755 insertions, 73 deletions
diff --git a/include/osmocom/msc/a_iface.h b/include/osmocom/msc/a_iface.h
index 217011d2e..9a758d36b 100644
--- a/include/osmocom/msc/a_iface.h
+++ b/include/osmocom/msc/a_iface.h
@@ -78,6 +78,8 @@ int a_iface_tx_assignment(const struct gsm_trans *trans);
/* Send clear command via A-interface */
int a_iface_tx_clear_cmd(struct gsm_subscriber_connection *conn);
+int a_iface_tx_classmark_request(const struct gsm_subscriber_connection *conn);
+
/* Clear all subscriber connections on a specified BSC
* (Helper function for a_iface_bssap.c) */
void a_clear_all(struct osmo_sccp_user *scu, const struct osmo_sccp_addr *bsc_addr);
diff --git a/include/osmocom/msc/gsm_data.h b/include/osmocom/msc/gsm_data.h
index ffe3afc6b..70ac93440 100644
--- a/include/osmocom/msc/gsm_data.h
+++ b/include/osmocom/msc/gsm_data.h
@@ -130,6 +130,13 @@ struct gsm_subscriber_connection {
uint16_t lac;
struct gsm_encr encr;
+ /* "Temporary" storage for the case the VLR asked for Cipher Mode Command, but the MSC still
+ * wants to request a Classmark Update first. */
+ struct {
+ bool umts_aka;
+ bool retrieve_imeisv;
+ } geran_set_cipher_mode;
+
/* N(SD) expected in the received frame, per flow (TS 24.007 11.2.3.2.3.2.2) */
uint8_t n_sd_next[4];
diff --git a/include/osmocom/msc/osmo_msc.h b/include/osmocom/msc/osmo_msc.h
index 7b3702abc..3ffb65c91 100644
--- a/include/osmocom/msc/osmo_msc.h
+++ b/include/osmocom/msc/osmo_msc.h
@@ -16,6 +16,8 @@ enum subscr_conn_fsm_event {
SUBSCR_CONN_E_INVALID = 0,
/* Accepted the initial Complete Layer 3 (starting to evaluate Authentication and Ciphering) */
SUBSCR_CONN_E_COMPLETE_LAYER_3,
+ /* Received Classmark Update, typically neede for Ciphering Mode Command */
+ SUBSCR_CONN_E_CLASSMARK_UPDATE,
/* LU or Process Access FSM has determined that this conn is good */
SUBSCR_CONN_E_ACCEPTED,
/* received first reply from MS in "real" CC, SMS, USSD communication */
@@ -33,6 +35,7 @@ enum subscr_conn_fsm_event {
enum subscr_conn_fsm_state {
SUBSCR_CONN_S_NEW,
SUBSCR_CONN_S_AUTH_CIPH,
+ SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE,
SUBSCR_CONN_S_ACCEPTED,
SUBSCR_CONN_S_COMMUNICATING,
SUBSCR_CONN_S_RELEASING,
@@ -62,6 +65,9 @@ int msc_compl_l3(struct gsm_subscriber_connection *conn,
struct msgb *msg, uint16_t chosen_channel);
void msc_dtap(struct gsm_subscriber_connection *conn, uint8_t link_id,
struct msgb *msg);
+int msc_classmark_request_then_cipher_mode_cmd(struct gsm_subscriber_connection *conn, bool umts_aka,
+ bool retrieve_imeisv);
+int msc_geran_set_cipher_mode(struct gsm_subscriber_connection *conn, bool umts_aka, bool retrieve_imeisv);
void msc_cipher_mode_compl(struct gsm_subscriber_connection *conn,
struct msgb *msg, uint8_t alg_id);
void msc_rx_sec_mode_compl(struct gsm_subscriber_connection *conn);
diff --git a/src/libmsc/a_iface.c b/src/libmsc/a_iface.c
index 75fa438e6..bd9b89035 100644
--- a/src/libmsc/a_iface.c
+++ b/src/libmsc/a_iface.c
@@ -422,6 +422,16 @@ int a_iface_tx_clear_cmd(struct gsm_subscriber_connection *conn)
return osmo_sccp_tx_data_msg(conn->a.scu, conn->a.conn_id, msg);
}
+int a_iface_tx_classmark_request(const struct gsm_subscriber_connection *conn)
+{
+ struct msgb *msg;
+
+ LOGPCONN(conn, LOGL_INFO, "Tx BSSMAP CLASSMARK REQUEST to BSC\n");
+
+ msg = gsm0808_create_classmark_request();
+ return osmo_sccp_tx_data_msg(conn->a.scu, conn->a.conn_id, msg);
+}
+
/* Callback function: Close all open connections */
static void a_reset_cb(const void *priv)
{
diff --git a/src/libmsc/gsm_04_08.c b/src/libmsc/gsm_04_08.c
index b942a0391..564e90bff 100644
--- a/src/libmsc/gsm_04_08.c
+++ b/src/libmsc/gsm_04_08.c
@@ -119,13 +119,16 @@ static bool classmark_is_r99(struct gsm_classmark *cm)
return classmark2_is_r99(cm->classmark2, cm->classmark2_len);
}
-/* Determine if the given CLASSMARK (1/2/3) value permits a given A5/n cipher */
-static bool classmark_supports_a5(const struct gsm_classmark *cm, uint8_t a5)
+/* Determine if the given CLASSMARK (1/2/3) value permits a given A5/n cipher.
+ * Return 1 when the given A5/n is permitted, 0 when not, and negative if the respective MS CLASSMARK is
+ * not known, where the negative number indicates the classmark type: -2 means Classmark 2 is not
+ * available. */
+static int classmark_supports_a5(const struct gsm_classmark *cm, uint8_t a5)
{
switch (a5) {
case 0:
/* all phones must implement A5/0, see 3GPP TS 43.020 4.9 */
- return true;
+ return 1;
case 1:
/* 3GPP TS 43.020 4.9 requires A5/1 to be suppored by all phones and actually states:
* "The network shall not provide service to an MS which indicates that it does not
@@ -134,25 +137,24 @@ static bool classmark_supports_a5(const struct gsm_classmark *cm, uint8_t a5)
/* See 3GPP TS 24.008 10.5.1.7 */
if (!cm->classmark1_set) {
DEBUGP(DMSC, "CLASSMARK 1 unknown, assuming MS supports A5/1\n");
- return true;
+ return -1;
} else {
if (cm->classmark1.a5_1)
- return false; /* Inverted logic for this bit! */
+ return 0; /* Inverted logic for this bit! */
else
- return true;
+ return 1;
}
break;
case 2:
case 3:
/* See 3GPP TS 24.008 10.5.1.6 */
if (cm->classmark2_len < 3) {
- DEBUGP(DMSC, "CLASSMARK 2 unknown, assuming MS doesn't support A5/%u\n", a5);
- return false;
+ return -2;
} else {
if (cm->classmark2[2] & (1 << (a5-2)))
- return true;
+ return 1;
else
- return false;
+ return 0;
}
break;
case 4:
@@ -161,13 +163,12 @@ static bool classmark_supports_a5(const struct gsm_classmark *cm, uint8_t a5)
case 7:
/* See 3GPP TS 24.008 10.5.1.7 */
if (cm->classmark3_len < 1) {
- DEBUGP(DMSC, "CLASSMARK 3 unknown, assuming MS doesn't support A5/%u\n", a5);
- return false;
+ return -3;
} else {
if (cm->classmark3[0] & (1 << (a5-4)))
- return true;
+ return 1;
else
- return false;
+ return 0;
}
break;
default:
@@ -1592,6 +1593,78 @@ static int msc_vlr_tx_cm_serv_rej(void *msc_conn_ref, enum gsm48_reject_value ca
osmo_static_assert(sizeof(((struct gsm0808_encrypt_info*)0)->key) >= sizeof(((struct osmo_auth_vector*)0)->kc),
gsm0808_encrypt_info_key_fits_osmo_auth_vec_kc);
+int msc_geran_set_cipher_mode(struct gsm_subscriber_connection *conn, bool umts_aka, bool retrieve_imeisv)
+{
+ struct gsm_network *net = conn->network;
+ struct gsm0808_encrypt_info ei;
+ int i, j = 0;
+ int request_classmark = 0;
+ int request_classmark_for_a5_n = 0;
+ struct gsm_auth_tuple *tuple = conn->vsub->last_tuple;
+
+ if (!conn || !conn->vsub || !conn->vsub->last_tuple) {
+ /* This should really never happen, because we checked this in msc_vlr_set_ciph_mode()
+ * already. */
+ LOGP(DMM, LOGL_ERROR, "Internal error: missing state during Ciphering Mode Command\n");
+ return -EINVAL;
+ }
+
+ for (i = 0; i < 8; i++) {
+ int supported;
+
+ /* A5/n permitted by osmo-msc.cfg? */
+ if (!(net->a5_encryption_mask & (1 << i)))
+ continue;
+
+ /* A5/n supported by MS? */
+ supported = classmark_supports_a5(&conn->vsub->classmark, i);
+ if (supported == 1) {
+ ei.perm_algo[j++] = vlr_ciph_to_gsm0808_alg_id(i);
+ /* A higher A5/n is supported, so no need to request a Classmark
+ * for support of a lesser A5/n. */
+ request_classmark = 0;
+ } else if (supported < 0) {
+ request_classmark = -supported;
+ request_classmark_for_a5_n = i;
+ }
+ }
+ ei.perm_algo_len = j;
+
+ if (request_classmark) {
+ /* The highest A5/n as from osmo-msc.cfg might be available, but we are
+ * still missing the Classmark information for that from the MS. First
+ * ask for that. */
+ LOGP(DMM, LOGL_DEBUG, "%s: to determine whether A5/%d is supported,"
+ " first ask for a Classmark Update to obtain Classmark %d\n",
+ vlr_subscr_name(conn->vsub), request_classmark_for_a5_n,
+ request_classmark);
+
+ return msc_classmark_request_then_cipher_mode_cmd(conn, umts_aka, retrieve_imeisv);
+ }
+
+ if (ei.perm_algo_len == 0) {
+ LOGP(DMM, LOGL_ERROR, "%s: cannot start ciphering, no intersection "
+ "between MSC-configured and MS-supported A5 algorithms\n",
+ vlr_subscr_name(conn->vsub));
+ return -ENOTSUP;
+ }
+
+ DEBUGP(DMM, "-> CIPHER MODE COMMAND %s\n", vlr_subscr_name(conn->vsub));
+
+ tuple = conn->vsub->last_tuple;
+
+ /* In case of UMTS AKA, the Kc for ciphering must be derived from the 3G auth
+ * tokens. tuple->vec.kc was calculated from the GSM algorithm and is not
+ * necessarily a match for the UMTS AKA tokens. */
+ if (umts_aka)
+ osmo_auth_c3(ei.key, tuple->vec.ck, tuple->vec.ik);
+ else
+ memcpy(ei.key, tuple->vec.kc, sizeof(tuple->vec.kc));
+ ei.key_len = sizeof(tuple->vec.kc);
+
+ return a_iface_tx_cipher_mode(conn, &ei, retrieve_imeisv);
+}
+
/* VLR asks us to start using ciphering.
* (Keep non-static to allow regression testing on this function.) */
int msc_vlr_set_ciph_mode(void *msc_conn_ref,
@@ -1620,38 +1693,7 @@ int msc_vlr_set_ciph_mode(void *msc_conn_ref,
switch (conn->via_ran) {
case RAN_GERAN_A:
- DEBUGP(DMM, "-> CIPHER MODE COMMAND %s\n",
- vlr_subscr_name(conn->vsub));
- {
- struct gsm_network *net = conn->network;
- struct gsm0808_encrypt_info ei;
- int i, j = 0;
-
- for (i = 0; i < 8; i++) {
- if (net->a5_encryption_mask & (1 << i) &&
- classmark_supports_a5(&conn->vsub->classmark, i))
- ei.perm_algo[j++] = vlr_ciph_to_gsm0808_alg_id(i);
- }
- ei.perm_algo_len = j;
-
- if (ei.perm_algo_len == 0) {
- LOGP(DMM, LOGL_ERROR, "%s: cannot start ciphering, no intersection "
- "between MSC-configured and MS-supported A5 algorithms\n",
- vlr_subscr_name(conn->vsub));
- return -ENOTSUP;
- }
-
- /* In case of UMTS AKA, the Kc for ciphering must be derived from the 3G auth
- * tokens. tuple->vec.kc was calculated from the GSM algorithm and is not
- * necessarily a match for the UMTS AKA tokens. */
- if (umts_aka)
- osmo_auth_c3(ei.key, tuple->vec.ck, tuple->vec.ik);
- else
- memcpy(ei.key, tuple->vec.kc, sizeof(tuple->vec.kc));
- ei.key_len = sizeof(tuple->vec.kc);
-
- return a_iface_tx_cipher_mode(conn, &ei, retrieve_imeisv);
- }
+ return msc_geran_set_cipher_mode(conn, umts_aka, retrieve_imeisv);
case RAN_UTRAN_IU:
#ifdef BUILD_IU
diff --git a/src/libmsc/osmo_msc.c b/src/libmsc/osmo_msc.c
index 1966043fd..8efa16ced 100644
--- a/src/libmsc/osmo_msc.c
+++ b/src/libmsc/osmo_msc.c
@@ -167,6 +167,10 @@ void msc_classmark_chg(struct gsm_subscriber_connection *conn,
cm->classmark3_len = cm3_len;
memcpy(cm->classmark3, cm3, cm3_len);
}
+
+ /* bump subscr conn FSM in case it is waiting for a Classmark Update */
+ if (conn->fi->state == SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE)
+ osmo_fsm_inst_dispatch(conn->fi, SUBSCR_CONN_E_CLASSMARK_UPDATE, NULL);
}
/* Receive a CIPHERING MODE COMPLETE from BSC */
diff --git a/src/libmsc/subscr_conn.c b/src/libmsc/subscr_conn.c
index 2040e369b..e6fa7e11f 100644
--- a/src/libmsc/subscr_conn.c
+++ b/src/libmsc/subscr_conn.c
@@ -45,6 +45,7 @@
static const struct value_string subscr_conn_fsm_event_names[] = {
OSMO_VALUE_STRING(SUBSCR_CONN_E_INVALID),
OSMO_VALUE_STRING(SUBSCR_CONN_E_COMPLETE_LAYER_3),
+ OSMO_VALUE_STRING(SUBSCR_CONN_E_CLASSMARK_UPDATE),
OSMO_VALUE_STRING(SUBSCR_CONN_E_ACCEPTED),
OSMO_VALUE_STRING(SUBSCR_CONN_E_COMMUNICATING),
OSMO_VALUE_STRING(SUBSCR_CONN_E_RELEASE_WHEN_UNUSED),
@@ -163,6 +164,66 @@ void subscr_conn_fsm_auth_ciph(struct osmo_fsm_inst *fi, uint32_t event, void *d
}
}
+int msc_classmark_request_then_cipher_mode_cmd(struct gsm_subscriber_connection *conn, bool umts_aka,
+ bool retrieve_imeisv)
+{
+ int rc;
+ conn->geran_set_cipher_mode.umts_aka = umts_aka;
+ conn->geran_set_cipher_mode.retrieve_imeisv = retrieve_imeisv;
+
+ rc = a_iface_tx_classmark_request(conn);
+ if (rc) {
+ LOGP(DMM, LOGL_ERROR, "%s: cannot send BSSMAP Classmark Request\n",
+ vlr_subscr_name(conn->vsub));
+ return -EIO;
+ }
+
+ osmo_fsm_inst_state_chg(conn->fi, SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE, SUBSCR_CONN_TIMEOUT, 0);
+ return 0;
+}
+
+static void subscr_conn_fsm_wait_classmark_update(struct osmo_fsm_inst *fi, uint32_t event, void *data)
+{
+ struct gsm_subscriber_connection *conn = fi->priv;
+ switch (event) {
+ case SUBSCR_CONN_E_CLASSMARK_UPDATE:
+ /* Theoretically, this event can be used for requesting Classmark in various situations.
+ * So far though, the only time we send a Classmark Request is during Ciphering. As soon
+ * as more such situations arise, we need to add state to indicate what action should
+ * follow after a Classmark Update is received (e.g.
+ * msc_classmark_request_then_cipher_mode_cmd() sets an enum value to indicate that
+ * Ciphering should continue afterwards). But right now, it is accurate to always
+ * continue with Ciphering: */
+
+ /* During Ciphering, we needed Classmark information. The Classmark Update has come in,
+ * go back into the Set Ciphering Command procedure. */
+ osmo_fsm_inst_state_chg(fi, SUBSCR_CONN_S_AUTH_CIPH, SUBSCR_CONN_TIMEOUT, 0);
+ if (msc_geran_set_cipher_mode(conn, conn->geran_set_cipher_mode.umts_aka,
+ conn->geran_set_cipher_mode.retrieve_imeisv)) {
+ LOGPFSML(fi, LOGL_ERROR,
+ "Sending Cipher Mode Command failed, aborting attach\n");
+ vlr_subscr_cancel_attach_fsm(conn->vsub, OSMO_FSM_TERM_ERROR,
+ GSM48_REJECT_NETWORK_FAILURE);
+ }
+ return;
+
+ case SUBSCR_CONN_E_UNUSED:
+ LOGPFSML(fi, LOGL_DEBUG, "Awaiting results for Auth+Ciph, overruling event %s\n",
+ osmo_fsm_event_name(fi->fsm, event));
+ return;
+
+ case SUBSCR_CONN_E_MO_CLOSE:
+ case SUBSCR_CONN_E_CN_CLOSE:
+ log_close_event(fi, event, data);
+ evaluate_acceptance_outcome(fi, false);
+ osmo_fsm_inst_state_chg(fi, SUBSCR_CONN_S_RELEASING, SUBSCR_CONN_TIMEOUT, 0);
+ return;
+
+ default:
+ OSMO_ASSERT(false);
+ }
+}
+
static bool subscr_conn_fsm_has_active_transactions(struct osmo_fsm_inst *fi)
{
struct gsm_subscriber_connection *conn = fi->priv;
@@ -362,10 +423,21 @@ static const struct osmo_fsm_state subscr_conn_fsm_states[] = {
S(SUBSCR_CONN_E_MO_CLOSE) |
S(SUBSCR_CONN_E_CN_CLOSE) |
S(SUBSCR_CONN_E_UNUSED),
- .out_state_mask = S(SUBSCR_CONN_S_ACCEPTED) |
+ .out_state_mask = S(SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE) |
+ S(SUBSCR_CONN_S_ACCEPTED) |
S(SUBSCR_CONN_S_RELEASING),
.action = subscr_conn_fsm_auth_ciph,
},
+ [SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE] = {
+ .name = OSMO_STRINGIFY(SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE),
+ .in_event_mask = S(SUBSCR_CONN_E_CLASSMARK_UPDATE) |
+ S(SUBSCR_CONN_E_MO_CLOSE) |
+ S(SUBSCR_CONN_E_CN_CLOSE) |
+ S(SUBSCR_CONN_E_UNUSED),
+ .out_state_mask = S(SUBSCR_CONN_S_AUTH_CIPH) |
+ S(SUBSCR_CONN_S_RELEASING),
+ .action = subscr_conn_fsm_wait_classmark_update,
+ },
[SUBSCR_CONN_S_ACCEPTED] = {
.name = OSMO_STRINGIFY(SUBSCR_CONN_S_ACCEPTED),
/* allow everything to release for any odd behavior */
diff --git a/tests/msc_vlr/Makefile.am b/tests/msc_vlr/Makefile.am
index e6b20e629..1d1956a15 100644
--- a/tests/msc_vlr/Makefile.am
+++ b/tests/msc_vlr/Makefile.am
@@ -35,6 +35,7 @@ AM_LDFLAGS = \
-Wl,--wrap=msc_mgcp_call_assignment \
-Wl,--wrap=a_iface_tx_cipher_mode \
-Wl,--wrap=ranap_iu_tx_sec_mode_cmd \
+ -Wl,--wrap=osmo_sccp_tx_data_msg \
$(NULL)
LDADD = \
diff --git a/tests/msc_vlr/msc_vlr_test_gsm_ciph.c b/tests/msc_vlr/msc_vlr_test_gsm_ciph.c
index add9f7f32..425406616 100644
--- a/tests/msc_vlr/msc_vlr_test_gsm_ciph.c
+++ b/tests/msc_vlr/msc_vlr_test_gsm_ciph.c
@@ -1053,8 +1053,11 @@ static void test_gsm_ciph_in_umts_env()
comment_end();
}
-static void test_a5_3_not_supported()
+static void test_a5_3_supported()
{
+ struct vlr_subscr *vsub;
+ const char *imsi = "901700000004620";
+
comment_start();
/* implicit: net->authentication_required = true; */
@@ -1093,12 +1096,403 @@ static void test_a5_3_not_supported()
VERBOSE_ASSERT(auth_request_sent, == true, "%d");
BTW("MS sends Authen Response, VLR accepts and wants to send Ciphering Mode Command to MS"
- " -- alas, no matching cipher can be found, abort and release");
+ " -- but needs Classmark 2 to determine whether A5/3 is supported");
cipher_mode_cmd_sent = false;
+ ms_sends_msg("05542d8b2c3e");
+ OSMO_ASSERT(!cipher_mode_cmd_sent);
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+ btw("BSC sends back a BSSMAP Classmark Update, that triggers the Ciphering Mode Command in A5/3");
+ expect_cipher_mode_cmd("61855fb81fc2a800");
+ bss_sends_bssap_mgmt("541203505886130b6014042f6503b8800d2100");
+ 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("04010809710000004026f0");
+ 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("10010809710000004026f00804032443f2",
+ "12010809710000004026f0");
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+ btw("HLR also sends GSUP _UPDATE_LOCATION_RESULT");
expect_bssap_clear();
+ gsup_rx("06010809710000004026f0", 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");
+ bss_sends_clear_complete();
+ EXPECT_CONN_COUNT(0);
+
+ BTW("after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector");
+ cm_service_result_sent = RES_NONE;
+ auth_request_sent = false;
+ auth_request_expect_rand = "12aca96fb4ffdea5c985cbafa9b6e18b";
+ ms_sends_msg("05247803305886089910070000006402");
+ OSMO_ASSERT(g_conn);
+ OSMO_ASSERT(g_conn->fi);
+ OSMO_ASSERT(g_conn->vsub);
+ VERBOSE_ASSERT(auth_request_sent, == true, "%d");
+ VERBOSE_ASSERT(cm_service_result_sent, == RES_NONE, "%d");
+
+ btw("needs auth, not yet accepted");
+ EXPECT_ACCEPTED(false);
+ thwart_rx_non_initial_requests();
+
+ btw("MS sends Authen Response, VLR accepts and requests Ciphering. We already know Classmark 3,"
+ " so no need to request Classmark Update.");
+ expect_cipher_mode_cmd("07fa7502e07e1c00");
+ ms_sends_msg("0554" "20bde240" /* 2nd vector's sres, s.a. */);
+ VERBOSE_ASSERT(cm_service_result_sent, == RES_NONE, "%d");
+ VERBOSE_ASSERT(cipher_mode_cmd_sent, == true, "%d");
+
+ btw("needs ciph, not yet accepted");
+ EXPECT_ACCEPTED(false);
+ thwart_rx_non_initial_requests();
+
+ 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");
+
+ /* Release connection */
+ expect_bssap_clear(RAN_GERAN_A);
+ conn_conclude_cm_service_req(g_conn, RAN_GERAN_A);
+
+ btw("all requests serviced, conn has been released");
+ bss_sends_clear_complete();
+ 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 Auth Request with third key");
+ auth_request_sent = false;
+ auth_request_expect_rand = "e7c03ba7cf0e2fde82b2dc4d63077d42";
+ ms_sends_msg("06270703305882089910070000006402");
+ VERBOSE_ASSERT(auth_request_sent, == true, "%d");
+
+ btw("needs auth, not yet accepted");
+ EXPECT_ACCEPTED(false);
+ thwart_rx_non_initial_requests();
+
+ btw("MS sends Authen Response, VLR accepts and requests Ciphering");
+ expect_cipher_mode_cmd("e2b234f807886400");
+ ms_sends_msg("0554" "a29514ae" /* 3rd vector's sres, s.a. */);
+ VERBOSE_ASSERT(cipher_mode_cmd_sent, == true, "%d");
+
+ btw("needs ciph, not yet accepted");
+ EXPECT_ACCEPTED(false);
+ thwart_rx_non_initial_requests();
+
+ btw("MS sends Ciphering Mode Complete, VLR accepts and sends pending SMS");
+ dtap_expect_tx("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");
+ 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");
+ bss_sends_clear_complete();
+ EXPECT_CONN_COUNT(0);
+
+ BTW("subscriber detaches");
+ expect_bssap_clear();
+ ms_sends_msg("050130089910070000006402");
+ VERBOSE_ASSERT(bssap_clear_sent, == true, "%d");
+
+ bss_sends_clear_complete();
+ EXPECT_CONN_COUNT(0);
+ clear_vlr();
+ comment_end();
+}
+
+/* During CM Service Request or Paging Response we already have Classmark 2 that indicates A5/3
+ * availablity. Here, in a hacky way remove the knowledge of Classmark 2 to tickle a code path where
+ * proc_arq_fsm needs a Classmark Update during Ciphering. Shouldn't happen in reality though. */
+static void test_cm_service_needs_classmark_update()
+{
+ struct vlr_subscr *vsub;
+ const char *imsi = "901700000004620";
+
+ comment_start();
+
+ /* A5/3 support is indicated in Classmark 3. By configuring A5/3, trigger the code paths that
+ * send a Classmark Request. */
+ net->a5_encryption_mask = (1 << 3); /* A5/3 */
+ /* implicit: net->authentication_required = true; */
+
+ btw("Location Update request causes a GSUP Send Auth Info request to HLR");
+ lu_result_sent = RES_NONE;
+ gsup_expect_tx("08010809710000004026f0");
+ ms_sends_msg("050802008168000130089910070000006402");
+ OSMO_ASSERT(gsup_tx_confirmed);
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+ btw("from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS");
+ /* Based on a Ki of 000102030405060708090a0b0c0d0e0f */
+ auth_request_sent = false;
+ auth_request_expect_rand = "585df1ae287f6e273dce07090d61320b";
+ auth_request_expect_autn = NULL;
+ gsup_rx("0a"
+ /* imsi */
+ "0108" "09710000004026f0"
+ /* 5 auth vectors... */
+ /* TL TL rand */
+ "0322" "2010" "585df1ae287f6e273dce07090d61320b"
+ /* TL sres TL kc */
+ "2104" "2d8b2c3e" "2208" "61855fb81fc2a800"
+ "0322" "2010" "12aca96fb4ffdea5c985cbafa9b6e18b"
+ "2104" "20bde240" "2208" "07fa7502e07e1c00"
+ "0322" "2010" "e7c03ba7cf0e2fde82b2dc4d63077d42"
+ "2104" "a29514ae" "2208" "e2b234f807886400"
+ "0322" "2010" "fa8f20b781b5881329d4fea26b1a3c51"
+ "2104" "5afc8d72" "2208" "2392f14f709ae000"
+ "0322" "2010" "0fd4cc8dbe8715d1f439e304edfd68dc"
+ "2104" "bc8d1c5b" "2208" "da7cdd6bfe2d7000",
+ NULL);
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+ VERBOSE_ASSERT(auth_request_sent, == true, "%d");
+
+ BTW("MS sends Authen Response, VLR accepts and wants to send Ciphering Mode Command to MS"
+ " -- but needs Classmark 2 to determine whether A5/3 is supported");
+ cipher_mode_cmd_sent = false;
ms_sends_msg("05542d8b2c3e");
OSMO_ASSERT(!cipher_mode_cmd_sent);
- VERBOSE_ASSERT(lu_result_sent, == RES_REJECT, "%d");
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+ btw("BSC sends back a BSSMAP Classmark Update, that triggers the Ciphering Mode Command in A5/3");
+ expect_cipher_mode_cmd("61855fb81fc2a800");
+ bss_sends_bssap_mgmt("541203505886130b6014042f6503b8800d2100");
+ 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("04010809710000004026f0");
+ 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("10010809710000004026f00804032443f2",
+ "12010809710000004026f0");
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+ btw("HLR also sends GSUP _UPDATE_LOCATION_RESULT");
+ expect_bssap_clear();
+ gsup_rx("06010809710000004026f0", 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");
+ bss_sends_clear_complete();
+ EXPECT_CONN_COUNT(0);
+
+
+ BTW("after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector");
+ cm_service_result_sent = RES_NONE;
+ auth_request_sent = false;
+ auth_request_expect_rand = "12aca96fb4ffdea5c985cbafa9b6e18b";
+ ms_sends_msg("05247803305886089910070000006402");
+ OSMO_ASSERT(g_conn);
+ OSMO_ASSERT(g_conn->fi);
+ OSMO_ASSERT(g_conn->vsub);
+ VERBOSE_ASSERT(auth_request_sent, == true, "%d");
+ VERBOSE_ASSERT(cm_service_result_sent, == RES_NONE, "%d");
+
+ btw("needs auth, not yet accepted");
+ EXPECT_ACCEPTED(false);
+ thwart_rx_non_initial_requests();
+
+ btw("MS sends Authen Response, VLR accepts and requests Ciphering. We already know Classmark 3,"
+ " so no need to request Classmark Update.");
+ expect_cipher_mode_cmd("07fa7502e07e1c00");
+ ms_sends_msg("0554" "20bde240" /* 2nd vector's sres, s.a. */);
+ VERBOSE_ASSERT(cm_service_result_sent, == RES_NONE, "%d");
+ VERBOSE_ASSERT(cipher_mode_cmd_sent, == true, "%d");
+
+ btw("needs ciph, not yet accepted");
+ EXPECT_ACCEPTED(false);
+ thwart_rx_non_initial_requests();
+
+ 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");
+
+ /* Release connection */
+ expect_bssap_clear(RAN_GERAN_A);
+ conn_conclude_cm_service_req(g_conn, RAN_GERAN_A);
+
+ btw("all requests serviced, conn has been released");
+ bss_sends_clear_complete();
+ 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 Auth Request with third key");
+ auth_request_sent = false;
+ auth_request_expect_rand = "e7c03ba7cf0e2fde82b2dc4d63077d42";
+ ms_sends_msg("06270703305882089910070000006402");
+ VERBOSE_ASSERT(auth_request_sent, == true, "%d");
+
+ BTW("Fake a situation where Classmark 2 is unknown during proc_arq_fsm");
+ vsub = vlr_subscr_find_by_imsi(net->vlr, imsi);
+ OSMO_ASSERT(vsub);
+ vsub->classmark.classmark2_len = 0;
+ vsub->classmark.classmark3_len = 0;
+ vlr_subscr_put(vsub);
+
+
+ btw("MS sends Authen Response, VLR accepts and requests Ciphering");
+ btw("MS sends Authen Response, VLR accepts and requests Ciphering."
+ " Normally, we'd know Classmark 3, but this test removed it."
+ " Hence a Classmark Request is generated.");
+ cipher_mode_cmd_sent = false;
+ ms_sends_msg("0554" "a29514ae" /* 3rd vector's sres, s.a. */);
+ OSMO_ASSERT(!cipher_mode_cmd_sent);
+
+ btw("BSC sends back a BSSMAP Classmark Update, that triggers the Ciphering Mode Command in A5/3");
+ expect_cipher_mode_cmd("e2b234f807886400");
+ bss_sends_bssap_mgmt("541203505886130b6014042f6503b8800d2100");
+ OSMO_ASSERT(cipher_mode_cmd_sent);
+
+ btw("needs ciph, not yet accepted");
+ EXPECT_ACCEPTED(false);
+
+ btw("MS sends Ciphering Mode Complete, VLR accepts and sends pending SMS");
+ dtap_expect_tx("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");
+ 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");
+ bss_sends_clear_complete();
+ EXPECT_CONN_COUNT(0);
+
+ BTW("subscriber detaches");
+ expect_bssap_clear();
+ ms_sends_msg("050130089910070000006402");
+ VERBOSE_ASSERT(bssap_clear_sent, == true, "%d");
bss_sends_clear_complete();
EXPECT_CONN_COUNT(0);
@@ -1114,6 +1508,7 @@ msc_vlr_test_func_t msc_vlr_tests[] = {
test_ciph_imeisv,
test_ciph_tmsi_imei,
test_gsm_ciph_in_umts_env,
- test_a5_3_not_supported,
+ test_a5_3_supported,
+ test_cm_service_needs_classmark_update,
NULL
};
diff --git a/tests/msc_vlr/msc_vlr_test_gsm_ciph.err b/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
index 6a00669cf..4a13b68a5 100644
--- a/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
+++ b/tests/msc_vlr/msc_vlr_test_gsm_ciph.err
@@ -2260,7 +2260,7 @@ DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
full talloc report on 'msgb' (total 0 bytes in 1 blocks)
talloc_total_blocks(tall_bsc_ctx) == 12
-===== test_a5_3_not_supported
+===== test_a5_3_supported
- 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
@@ -2309,7 +2309,7 @@ DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
lu_result_sent == 0
auth_request_sent == 1
---
-- MS sends Authen Response, VLR accepts and wants to send Ciphering Mode Command to MS -- alas, no matching cipher can be found, abort and release
+- MS sends Authen Response, VLR accepts and wants to send Ciphering Mode Command to MS -- but needs Classmark 2 to determine whether A5/3 is supported
MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2: dtap)
DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
@@ -2326,23 +2326,598 @@ DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
+DMM IMSI:901700000004620: to determine whether A5/3 is supported, first ask for a Classmark Update to obtain Classmark 2
+ BSC <--BSSAP-BSS-MANAGEMENT-- MSC: CLASSMARK REQ [L3]> 00 01 58
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
+DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0: )
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ lu_result_sent == 0
+- BSC sends back a BSSMAP Classmark Update, that triggers the Ciphering Mode Command in A5/3
+DMSC Looking for A subscriber: conn_id 0
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event SUBSCR_CONN_E_CLASSMARK_UPDATE
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
DMM -> CIPHER MODE COMMAND IMSI:901700000004620
-DMSC CLASSMARK 2 unknown, assuming MS doesn't support A5/3
-DMM IMSI:901700000004620: cannot start ciphering, no intersection between MSC-configured and MS-supported A5 algorithms
-- ERROR sending ciphering mode command: rc=-95
-DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Failed to send Ciphering Mode Command
-- sending LU Reject for IMSI:901700000004620, cause 17
-DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
-DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_CN_CLOSE
-DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_RELEASING
-DREF IMSI:901700000004620: MSC conn use + release == 2 (0x102: dtap,release)
+- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=0
+- ...perm algo: A5/3
+- ...key: 61855fb81fc2a800
+ 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:901700000004620: CIPHERING MODE COMPLETE
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
+DVLR GSUP tx: 04010809710000004026f0
+GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){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: 10010809710000004026f00804032443f2
+DVLR GSUP rx 17: 10010809710000004026f00804032443f2
+DREF VLR subscr IMSI:901700000004620 usage increases to: 2
+DVLR IMSI:901700000004620 has MSISDN:42342
+DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000004620 (MSISDN=42342, used=2)
+DVLR GSUP tx: 12010809710000004026f0
+GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
+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: 06010809710000004026f0
+DVLR GSUP rx 11: 06010809710000004026f0
+DREF VLR subscr MSISDN:42342 usage increases to: 2
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
+DVLR lu_compl_vlr_fsm(LU:901700000004620){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(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
+DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
+DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage decreases to: 3
+- BSSAP Clear --RAN_GERAN_A--> MS
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+<-- 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
+- BSS sends BSSMAP Clear Complete
+DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
+DRLL MSISDN:42342: Freeing subscriber connection
+DREF VLR subscr MSISDN:42342 usage decreases to: 1
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+ llist_count(&net->subscr_conns) == 0
+---
+- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
+ new conn
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
+DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
+DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Allocated
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(CM_SERVICE_REQ:901700000004620)
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){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(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620)
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
+- sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x1 and...
+- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
+- ...expecting sres=20bde240
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
+DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ auth_request_sent == 1
+ cm_service_result_sent == 0
+- 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 Authen Response, VLR accepts and requests Ciphering. We already know Classmark 3, so no need to request Classmark Update.
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
+DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
+DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
+DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
+DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 20bde240 (4 bytes)
+DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620)
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
+DMM -> CIPHER MODE COMMAND MSISDN:42342
+- sending Ciphering Mode Command for MSISDN:42342: include_imeisv=0
+- ...perm algo: A5/3
+- ...key: 07fa7502e07e1c00
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
+DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ cm_service_result_sent == 0
+ cipher_mode_cmd_sent == 1
+- needs ciph, 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 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(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
+DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service)
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
+ cm_service_result_sent == 0
+- Concluding CM Service Request
+DREF MSISDN:42342: MSC conn use - cm_service == 0 (0x0: )
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
+DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
+DREF VLR subscr MSISDN:42342 usage increases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+- BSSAP Clear --RAN_GERAN_A--> MS
+ bssap_clear_sent == 1
+- all requests serviced, conn has been released
+- BSS sends BSSMAP Clear Complete
+DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000004620)
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Freeing instance
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Deallocated
+DRLL MSISDN:42342: Freeing subscriber connection
+DREF VLR subscr MSISDN:42342 usage decreases to: 1
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+ 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 901700000004620, 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 Auth Request with third key
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
+ new conn
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
+DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
+DRR PAGING RESPONSE: MI(IMSI)=901700000004620
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Allocated
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){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(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(PAGING_RESP:901700000004620)
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
+- sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x1 and...
+- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
+- ...expecting sres=a29514ae
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
+DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ 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 Authen Response, VLR accepts and requests Ciphering
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
+DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
+DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
+DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
+DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: a29514ae (4 bytes)
+DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(PAGING_RESP:901700000004620)
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
+DMM -> CIPHER MODE COMMAND MSISDN:42342
+- sending Ciphering Mode Command for MSISDN:42342: include_imeisv=0
+- ...perm algo: A5/3
+- ...key: e2b234f807886400
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
+DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ cipher_mode_cmd_sent == 1
+- needs ciph, 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 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(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
+DPAG Paging success for MSISDN:42342 (event=0)
+DPAG Calling paging cbfn.
+DCC (ti 00 sub MSISDN:42342 callref 40000004) New transaction
+DREF VLR subscr MSISDN:42342 usage increases to: 5
+DREF MSISDN:42342: MSC conn use + trans_sms == 1 (0x20: trans_sms)
+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(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: 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 == 2 (0x22: dtap,trans_sms)
+DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
+DREF MSISDN:42342: MSC conn use - dtap == 1 (0x20: trans_sms)
+ 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 == 2 (0x22: dtap,trans_sms)
+DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
+DMM Subscr_Conn(PAGING_RESP:901700000004620){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 == 1 (0x2: dtap)
+DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
+DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
+DREF VLR subscr MSISDN:42342 usage increases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+- BSSAP Clear --RAN_GERAN_A--> MS
+ dtap_tx_confirmed == 1
+ bssap_clear_sent == 1
+- SMS is done, conn is gone
+- BSS sends BSSMAP Clear Complete
+DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(PAGING_RESP:901700000004620)
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Freeing instance
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Deallocated
+DRLL MSISDN:42342: Freeing subscriber connection
+DREF VLR subscr MSISDN:42342 usage decreases to: 1
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+ llist_count(&net->subscr_conns) == 0
+---
+- subscriber detaches
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
+ new conn
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
+DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
+DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
+DREF VLR subscr MSISDN:42342 usage increases to: 2
+DMM IMSI DETACH for MSISDN:42342
+DREF VLR subscr MSISDN:42342 usage increases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+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 Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
+DREF unknown: MSC conn use + release == 2 (0x101: compl_l3,release)
+- BSSAP Clear --RAN_GERAN_A--> MS
+DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release)
+ bssap_clear_sent == 1
+- BSS sends BSSMAP Clear Complete
+DREF unknown: MSC conn use - release == 0 (0x0: )
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DRLL Freeing subscriber connection with NULL subscriber
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
+ llist_count(&net->subscr_conns) == 0
+===== test_a5_3_supported: SUCCESS
+
+full talloc report on 'msgb' (total 0 bytes in 1 blocks)
+talloc_total_blocks(tall_bsc_ctx) == 12
+
+===== test_cm_service_needs_classmark_update
+- 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
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
+DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
+DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
+DMM LU/new-LAC: 1/23
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
+DVLR vlr_lu_fsm(LU:901700000004620){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=901700000004620 id=901700000004620
+DVLR New subscr, IMSI: 901700000004620
DREF VLR subscr IMSI:901700000004620 usage increases to: 2
DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000004620)
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
+DVLR GSUP tx: 08010809710000004026f0
+GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
+DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ lu_result_sent == 0
+- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
+<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
+DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
+DREF VLR subscr IMSI:901700000004620 usage increases to: 2
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
+DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
+- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
+- ...rand=585df1ae287f6e273dce07090d61320b
+- ...expecting sres=2d8b2c3e
+DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
+<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
+ lu_result_sent == 0
+ auth_request_sent == 1
+---
+- MS sends Authen Response, VLR accepts and wants to send Ciphering Mode Command to MS -- but needs Classmark 2 to determine whether A5/3 is supported
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
+DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2: dtap)
+DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
+DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
+DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
+DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000004620)
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
+DMM IMSI:901700000004620: to determine whether A5/3 is supported, first ask for a Classmark Update to obtain Classmark 2
+ BSC <--BSSAP-BSS-MANAGEMENT-- MSC: CLASSMARK REQ [L3]> 00 01 58
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
+DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0: )
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ lu_result_sent == 0
+- BSC sends back a BSSMAP Classmark Update, that triggers the Ciphering Mode Command in A5/3
+DMSC Looking for A subscriber: conn_id 0
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event SUBSCR_CONN_E_CLASSMARK_UPDATE
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
+DMM -> CIPHER MODE COMMAND IMSI:901700000004620
+- sending Ciphering Mode Command for IMSI:901700000004620: include_imeisv=0
+- ...perm algo: A5/3
+- ...key: 61855fb81fc2a800
+ 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:901700000004620: CIPHERING MODE COMPLETE
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
+DVLR GSUP tx: 04010809710000004026f0
+GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){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: 10010809710000004026f00804032443f2
+DVLR GSUP rx 17: 10010809710000004026f00804032443f2
+DREF VLR subscr IMSI:901700000004620 usage increases to: 2
+DVLR IMSI:901700000004620 has MSISDN:42342
+DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000004620 (MSISDN=42342, used=2)
+DVLR GSUP tx: 12010809710000004026f0
+GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
+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: 06010809710000004026f0
+DVLR GSUP rx 11: 06010809710000004026f0
+DREF VLR subscr MSISDN:42342 usage increases to: 2
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
+DVLR upd_hlr_vlr_fsm(LU:901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000004620)
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000004620)
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000004620)
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
+DVLR sub_pres_vlr_fsm(LU:901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
+DVLR lu_compl_vlr_fsm(LU:901700000004620){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(LU:901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000004620)
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
+DVLR lu_compl_vlr_fsm(LU:901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
+DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
+DREF VLR subscr MSISDN:42342 usage increases to: 4
+DREF VLR subscr MSISDN:42342 usage decreases to: 3
- BSSAP Clear --RAN_GERAN_A--> MS
-DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x100: release)
- lu_result_sent == 2
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+<-- 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
- BSS sends BSSMAP Clear Complete
-DREF IMSI:901700000004620: MSC conn use - release == 0 (0x0: )
+DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
@@ -2351,13 +2926,327 @@ DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr
DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
-DRLL IMSI:901700000004620: Freeing subscriber connection
-DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
-DREF freeing VLR subscr IMSI:901700000004620
+DRLL MSISDN:42342: Freeing subscriber connection
+DREF VLR subscr MSISDN:42342 usage decreases to: 1
DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
llist_count(&net->subscr_conns) == 0
-===== test_a5_3_not_supported: SUCCESS
+---
+- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
+ new conn
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
+DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
+DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: Allocated
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(CM_SERVICE_REQ:901700000004620)
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){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(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620)
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
+- sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x1 and...
+- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
+- ...expecting sres=20bde240
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
+DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ auth_request_sent == 1
+ cm_service_result_sent == 0
+- 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 Authen Response, VLR accepts and requests Ciphering. We already know Classmark 3, so no need to request Classmark Update.
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
+DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
+DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
+DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
+DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 20bde240 (4 bytes)
+DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620)
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
+DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
+DMM -> CIPHER MODE COMMAND MSISDN:42342
+- sending Ciphering Mode Command for MSISDN:42342: include_imeisv=0
+- ...perm algo: A5/3
+- ...key: 07fa7502e07e1c00
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
+DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ cm_service_result_sent == 0
+ cipher_mode_cmd_sent == 1
+- needs ciph, 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 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(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
+DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service)
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
+ cm_service_result_sent == 0
+- Concluding CM Service Request
+DREF MSISDN:42342: MSC conn use - cm_service == 0 (0x0: )
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
+DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
+DREF VLR subscr MSISDN:42342 usage increases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+- BSSAP Clear --RAN_GERAN_A--> MS
+ bssap_clear_sent == 1
+- all requests serviced, conn has been released
+- BSS sends BSSMAP Clear Complete
+DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000004620)
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Freeing instance
+DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000004620){PR_ARQ_S_DONE}: Deallocated
+DRLL MSISDN:42342: Freeing subscriber connection
+DREF VLR subscr MSISDN:42342 usage decreases to: 1
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(CM_SERVICE_REQ:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+ 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 901700000004620, 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 Auth Request with third key
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
+ new conn
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
+DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
+DRR PAGING RESPONSE: MI(IMSI)=901700000004620
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: Allocated
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000004620)
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth+Ciph
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){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(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(PAGING_RESP:901700000004620)
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
+- sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x1 and...
+- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
+- ...expecting sres=a29514ae
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
+DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ auth_request_sent == 1
+---
+- Fake a situation where Classmark 2 is unknown during proc_arq_fsm
+DREF VLR subscr MSISDN:42342 usage increases to: 5
+DREF VLR subscr MSISDN:42342 usage decreases to: 4
+- MS sends Authen Response, VLR accepts and requests Ciphering
+- MS sends Authen Response, VLR accepts and requests Ciphering. Normally, we'd know Classmark 3, but this test removed it. Hence a Classmark Request is generated.
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
+DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
+DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
+DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
+DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: a29514ae (4 bytes)
+DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(PAGING_RESP:901700000004620)
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
+DVLR VLR_Authenticate(PAGING_RESP:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
+DMM MSISDN:42342: to determine whether A5/3 is supported, first ask for a Classmark Update to obtain Classmark 2
+ BSC <--BSSAP-BSS-MANAGEMENT-- MSC: CLASSMARK REQ [L3]> 00 01 58
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
+DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+- BSC sends back a BSSMAP Classmark Update, that triggers the Ciphering Mode Command in A5/3
+DMSC Looking for A subscriber: conn_id 0
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event SUBSCR_CONN_E_CLASSMARK_UPDATE
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
+DMM -> CIPHER MODE COMMAND MSISDN:42342
+- sending Ciphering Mode Command for MSISDN:42342: include_imeisv=0
+- ...perm algo: A5/3
+- ...key: e2b234f807886400
+- needs ciph, not yet accepted
+msc_subscr_conn_is_accepted() == false
+- 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(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Process Access Request result: PASSED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
+DPAG Paging success for MSISDN:42342 (event=0)
+DPAG Calling paging cbfn.
+DCC (ti 00 sub MSISDN:42342 callref 40000005) New transaction
+DREF VLR subscr MSISDN:42342 usage increases to: 5
+DREF MSISDN:42342: MSC conn use + trans_sms == 1 (0x20: trans_sms)
+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(PAGING_RESP:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: 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 == 2 (0x22: dtap,trans_sms)
+DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
+DREF MSISDN:42342: MSC conn use - dtap == 1 (0x20: trans_sms)
+ 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 == 2 (0x22: dtap,trans_sms)
+DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
+DMM Subscr_Conn(PAGING_RESP:901700000004620){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 == 1 (0x2: dtap)
+DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
+DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
+DREF VLR subscr MSISDN:42342 usage increases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+- BSSAP Clear --RAN_GERAN_A--> MS
+ dtap_tx_confirmed == 1
+ bssap_clear_sent == 1
+- SMS is done, conn is gone
+- BSS sends BSSMAP Clear Complete
+DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(PAGING_RESP:901700000004620)
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Freeing instance
+DVLR Process_Access_Request_VLR(PAGING_RESP:901700000004620){PR_ARQ_S_DONE}: Deallocated
+DRLL MSISDN:42342: Freeing subscriber connection
+DREF VLR subscr MSISDN:42342 usage decreases to: 1
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(PAGING_RESP:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+ llist_count(&net->subscr_conns) == 0
+---
+- subscriber detaches
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
+ new conn
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
+DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
+DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
+DREF VLR subscr MSISDN:42342 usage increases to: 2
+DMM IMSI DETACH for MSISDN:42342
+DREF VLR subscr MSISDN:42342 usage increases to: 3
+DREF VLR subscr MSISDN:42342 usage decreases to: 2
+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 Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING
+DREF unknown: MSC conn use + release == 2 (0x101: compl_l3,release)
+- BSSAP Clear --RAN_GERAN_A--> MS
+DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release)
+ bssap_clear_sent == 1
+- BSS sends BSSMAP Clear Complete
+DREF unknown: MSC conn use - release == 0 (0x0: )
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DRLL Freeing subscriber connection with NULL subscriber
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
+ llist_count(&net->subscr_conns) == 0
+===== test_cm_service_needs_classmark_update: SUCCESS
full talloc report on 'msgb' (total 0 bytes in 1 blocks)
talloc_total_blocks(tall_bsc_ctx) == 12
diff --git a/tests/msc_vlr/msc_vlr_test_ms_timeout.c b/tests/msc_vlr/msc_vlr_test_ms_timeout.c
index c5ab0590e..ddb6324f8 100644
--- a/tests/msc_vlr/msc_vlr_test_ms_timeout.c
+++ b/tests/msc_vlr/msc_vlr_test_ms_timeout.c
@@ -292,9 +292,79 @@ static void test_ms_timeout_paging()
comment_end();
}
+static void test_classmark_update_timeout()
+{
+ comment_start();
+
+ fake_time_start();
+
+ /* implicit: net->authentication_required = true; */
+ net->a5_encryption_mask = (1 << 3); /* A5/3 */
+
+ btw("Location Update request causes a GSUP Send Auth Info request to HLR");
+ lu_result_sent = RES_NONE;
+ gsup_expect_tx("08010809710000004026f0");
+ ms_sends_msg("050802008168000130089910070000006402");
+ OSMO_ASSERT(gsup_tx_confirmed);
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+ btw("from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS");
+ /* Based on a Ki of 000102030405060708090a0b0c0d0e0f */
+ auth_request_sent = false;
+ auth_request_expect_rand = "585df1ae287f6e273dce07090d61320b";
+ auth_request_expect_autn = NULL;
+ gsup_rx("0a"
+ /* imsi */
+ "0108" "09710000004026f0"
+ /* TL TL rand */
+ "0322" "2010" "585df1ae287f6e273dce07090d61320b"
+ /* TL sres TL kc */
+ "2104" "2d8b2c3e" "2208" "61855fb81fc2a800"
+ ,
+ NULL);
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+ VERBOSE_ASSERT(auth_request_sent, == true, "%d");
+
+ BTW("MS sends Authen Response, VLR accepts and wants to send Ciphering Mode Command to MS"
+ " -- but needs Classmark 2 to determine whether A5/3 is supported");
+ cipher_mode_cmd_sent = false;
+ ms_sends_msg("05542d8b2c3e");
+ OSMO_ASSERT(!cipher_mode_cmd_sent);
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+
+ BTW("But the BSSMAP Classmark Update never arrives");
+ btw("At first, we're still waiting");
+ fake_time_passes(0, 423);
+ EXPECT_CONN_COUNT(1);
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+ fake_time_passes(1, 235);
+ EXPECT_CONN_COUNT(1);
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+ fake_time_passes(1, 235);
+ EXPECT_CONN_COUNT(1);
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+ fake_time_passes(1, 235);
+ EXPECT_CONN_COUNT(1);
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+ fake_time_passes(1, 235);
+ EXPECT_CONN_COUNT(1);
+ VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d");
+ expect_bssap_clear();
+ fake_time_passes(1, 235);
+ btw("SUBSCR_CONN_TIMEOUT has passed, conn is gone.");
+ VERBOSE_ASSERT(bssap_clear_sent, == true, "%d");
+ bss_sends_clear_complete();
+ EXPECT_CONN_COUNT(0);
+ VERBOSE_ASSERT(lu_result_sent, == RES_REJECT, "%d");
+
+ comment_end();
+}
+
+
msc_vlr_test_func_t msc_vlr_tests[] = {
test_ms_timeout_lu_auth_resp,
test_ms_timeout_cm_auth_resp,
test_ms_timeout_paging,
+ test_classmark_update_timeout,
NULL
};
diff --git a/tests/msc_vlr/msc_vlr_test_ms_timeout.err b/tests/msc_vlr/msc_vlr_test_ms_timeout.err
index eb40a97d2..43eb3d4a3 100644
--- a/tests/msc_vlr/msc_vlr_test_ms_timeout.err
+++ b/tests/msc_vlr/msc_vlr_test_ms_timeout.err
@@ -554,6 +554,136 @@ DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated
full talloc report on 'msgb' (total 0 bytes in 1 blocks)
talloc_total_blocks(tall_bsc_ctx) == 12
+===== test_classmark_update_timeout
+- Total time passed: 0.000000 s
+- 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
+DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
+DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
+DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID
+DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
+DMM LU/new-LAC: 1/23
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620)
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph
+DVLR vlr_lu_fsm(LU:901700000004620){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=901700000004620 id=901700000004620
+DVLR New subscr, IMSI: 901700000004620
+DREF VLR subscr IMSI:901700000004620 usage increases to: 2
+DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000004620)
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
+DVLR GSUP tx: 08010809710000004026f0
+GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
+DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: )
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ lu_result_sent == 0
+- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
+<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a800
+DVLR GSUP rx 47: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a800
+DREF VLR subscr IMSI:901700000004620 usage increases to: 2
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
+DVLR SUBSCR(IMSI:901700000004620) Received 1 auth tuples
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
+- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
+- ...rand=585df1ae287f6e273dce07090d61320b
+- ...expecting sres=2d8b2c3e
+DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
+<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
+ lu_result_sent == 0
+ auth_request_sent == 1
+---
+- MS sends Authen Response, VLR accepts and wants to send Ciphering Mode Command to MS -- but needs Classmark 2 to determine whether A5/3 is supported
+ MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
+DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2: dtap)
+DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
+DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
+DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
+DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000004620)
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
+DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
+DMM IMSI:901700000004620: to determine whether A5/3 is supported, first ask for a Classmark Update to obtain Classmark 2
+ BSC <--BSSAP-BSS-MANAGEMENT-- MSC: CLASSMARK REQ [L3]> 00 01 58
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
+DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0: )
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
+ lu_result_sent == 0
+---
+- But the BSSMAP Classmark Update never arrives
+- At first, we're still waiting
+- Total time passed: 0.000423 s
+ llist_count(&net->subscr_conns) == 1
+ lu_result_sent == 0
+- Total time passed: 1.000658 s
+ llist_count(&net->subscr_conns) == 1
+ lu_result_sent == 0
+- Total time passed: 2.000893 s
+ llist_count(&net->subscr_conns) == 1
+ lu_result_sent == 0
+- Total time passed: 3.001128 s
+ llist_count(&net->subscr_conns) == 1
+ lu_result_sent == 0
+- Total time passed: 4.001363 s
+ llist_count(&net->subscr_conns) == 1
+ lu_result_sent == 0
+- Total time passed: 5.001598 s
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Timeout of T0
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event SUBSCR_CONN_E_CN_CLOSE
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Close event, cause: CONGESTION
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: state_chg to SUBSCR_CONN_S_RELEASING
+DREF IMSI:901700000004620: MSC conn use + release == 1 (0x100: release)
+DREF VLR subscr IMSI:901700000004620 usage increases to: 2
+- sending LU Reject for IMSI:901700000004620, cause 22
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_DONE
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_CN_CLOSE
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Event SUBSCR_CONN_E_CN_CLOSE not permitted
+DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
+- BSSAP Clear --RAN_GERAN_A--> MS
+- SUBSCR_CONN_TIMEOUT has passed, conn is gone.
+ bssap_clear_sent == 1
+- BSS sends BSSMAP Clear Complete
+DREF IMSI:901700000004620: MSC conn use - release == 0 (0x0: )
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620)
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance
+DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated
+DRLL IMSI:901700000004620: Freeing subscriber connection
+DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
+DREF freeing VLR subscr IMSI:901700000004620
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
+DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
+ llist_count(&net->subscr_conns) == 0
+ lu_result_sent == 2
+===== test_classmark_update_timeout: SUCCESS
+
+full talloc report on 'msgb' (total 0 bytes in 1 blocks)
+talloc_total_blocks(tall_bsc_ctx) == 12
+
full talloc report on 'msgb' (total 0 bytes in 1 blocks)
talloc_total_blocks(tall_bsc_ctx) == 12
diff --git a/tests/msc_vlr/msc_vlr_tests.c b/tests/msc_vlr/msc_vlr_tests.c
index bf1b20056..1192cf210 100644
--- a/tests/msc_vlr/msc_vlr_tests.c
+++ b/tests/msc_vlr/msc_vlr_tests.c
@@ -35,6 +35,7 @@
#include <osmocom/msc/debug.h>
#include <osmocom/msc/gsm_04_08.h>
#include <osmocom/msc/transaction.h>
+#include <osmocom/msc/a_iface_bssap.h>
#if BUILD_IU
#include <osmocom/msc/iucs_ranap.h>
@@ -111,10 +112,10 @@ static void reset_l3_seq_nr()
struct msgb *msgb_from_hex(const char *label, uint16_t size, const char *hex)
{
- struct msgb *msg = msgb_alloc(size, label);
+ struct msgb *msg = msgb_alloc_headroom(size, 4, label);
unsigned char *rc;
- msg->l2h = msg->head;
- rc = msgb_put(msg, osmo_hexparse(hex, msg->head, msgb_tailroom(msg)));
+ msg->l2h = msg->data;
+ rc = msgb_put(msg, osmo_hexparse(hex, msg->data, msgb_tailroom(msg)));
OSMO_ASSERT(rc == msg->l2h);
return msg;
}
@@ -240,7 +241,32 @@ void ms_sends_msg(const char *hex)
msg = msgb_from_hex("ms_sends_msg", 1024, hex);
msg->l1h = msg->l2h = msg->l3h = msg->data;
rx_from_ms(msg);
- talloc_free(msg);
+ msgb_free(msg);
+}
+
+void bss_sends_bssap_mgmt(const char *hex)
+{
+ struct msgb *msg;
+ struct bssmap_header *bh;
+ struct a_conn_info a_conn_info;
+
+ msg = msgb_from_hex("bss_sends_bssap_mgmt", 1024, hex);
+ msg->l3h = msg->data;
+
+ msg->l2h = msgb_push(msg, sizeof(*bh));
+ bh = (void*)msg->l2h;
+ bh->type = BSSAP_MSG_BSS_MANAGEMENT;
+ bh->length = msgb_l3len(msg);
+
+ if (g_conn && !conn_exists(g_conn))
+ g_conn = NULL;
+
+ OSMO_ASSERT(g_conn);
+ a_conn_info.network = net;
+ a_conn_info.conn_id = g_conn->a.conn_id;
+
+ a_sccp_rx_dt((struct osmo_sccp_user*)0x1, &a_conn_info, msg);
+ msgb_free(msg);
}
static int ms_sends_msg_fake(uint8_t pdisc, uint8_t msg_type)
@@ -363,6 +389,33 @@ void __wrap_msc_stop_paging(struct vlr_subscr *vsub)
paging_stopped = true;
}
+
+/* override, requires '-Wl,--wrap=osmo_sccp_tx_data_msg' */
+int __real_osmo_sccp_tx_data_msg(struct osmo_sccp_user *scu, uint32_t conn_id,
+ struct msgb *msg);
+int __wrap_osmo_sccp_tx_data_msg(struct osmo_sccp_user *scu, uint32_t conn_id,
+ struct msgb *msg)
+{
+ const char *proto_str;
+ const char *msg_str = gsm0808_bssmap_name(msg->l3h[2]);
+ switch (*msg->l3h) {
+ case BSSAP_MSG_BSS_MANAGEMENT:
+ proto_str = "BSSAP-BSS-MANAGEMENT";
+ break;
+ case BSSAP_MSG_DTAP:
+ proto_str = "BSSAP-DTAP";
+ break;
+ default:
+ proto_str = "";
+ msg_str = "";
+ break;
+ }
+
+ log("BSC <--%s-- MSC: %s %s", proto_str, msg_str, msgb_hexdump(msg));
+ msgb_free(msg);
+ return 0;
+}
+
void clear_vlr()
{
struct vlr_subscr *vsub, *n;
diff --git a/tests/msc_vlr/msc_vlr_tests.h b/tests/msc_vlr/msc_vlr_tests.h
index 4ca05d29f..cc200bdff 100644
--- a/tests/msc_vlr/msc_vlr_tests.h
+++ b/tests/msc_vlr/msc_vlr_tests.h
@@ -161,6 +161,7 @@ void dtap_expect_tx_ussd(char *ussd_text);
void paging_expect_imsi(const char *imsi);
void paging_expect_tmsi(uint32_t tmsi);
+void bss_sends_bssap_mgmt(const char *hex);
void ms_sends_msg(const char *hex);
void ms_sends_security_mode_complete();
void gsup_rx(const char *rx_hex, const char *expect_tx_hex);
generated by cgit v1.2.3 (git 2.25.1) at 2024-06-12 23:00:45 +0000