From 3117b701c8d4645215896c459d6c608358a0a51b Mon Sep 17 00:00:00 2001 From: Neels Hofmeyr Date: Thu, 13 Sep 2018 03:23:07 +0200 Subject: [PATCH] A5/n Ciph: request Classmark Update if missing When the VLR requests a Ciphering Mode with vlr_ops.set_ciph_mode(), and if we need a ciph algo flag from a Classmark information that is not yet known (usually CM 2 during LU), send a BSSMAP Classmark Request to get it. To manage the intermission of the Classmark Request, add - msc_classmark_request_then_cipher_mode_cmd(), - state SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE, - event SUBSCR_CONN_E_CLASSMARK_UPDATE. From state AUTH_CIPH, switch to state WAIT_CLASSMARK_UPDATE. Once the BSSMAP Classmark Response, is received, switch back to SUBSCR_CONN_S_AUTH_CIPH and re-initiate Ciphering Mode. To be able to re-enter the Ciphering Mode algo decision, factor it out into msc_geran_set_cipher_mode(). Rationale: In the following commit, essentially we stopped supporting A5/3 ciphering: commit 71330720b6efdda2fcfd3e9c0cb45f89e32e5670 "MSC: Intersect configured A5 algorithms with MS-supported ones" Change-Id: Id124923ee52a357cb7d3e04d33f585214774f3a3 A5/3 was no longer supported because from that commit on, we strictly checked the MS-supported ciphers, but we did not have Classmark 2 available during Location Updating. This patch changes that: when Classmark 2 is missing, actively request it by a BSSMAP Classmark Request; continue Ciphering only after the Response. Always request missing Classmark, even if a lesser cipher were configured available. If the Classmark Update response fails to come in, cause an attach failure. Instead, we could attempt to use a lesser cipher that is also enabled. That is left as a future feature, should that become relevant. I think it's unlikely. Technically, we could now end up requesting a Classmark Updating both during LU (vlr_lu_fsm) and CM Service/Paging Response (proc_arq_fsm), but in practice the only time we lack a Classmark is: during Location Updating with A5/3 enabled. A5/1 support is indicated in CM1 which is always available, and A5/3 support is indicated in CM2, which is always available during CM Service Request as well as Paging Response. So this patch has practical relevance only for Location Updating. For networks that permit only A5/3, this patch fixes Location Updating. For networks that support A5/3 and A5/1, so far we always used A5/1 during LU, and after this patch we request CM2 and likely use A5/3 instead. In msc_vlr_test_gsm_ciph, verify that requesting Classmark 2 for A5/3 works during LU. Also verify that the lack of a Classmark Response results in attach failure. In msc_vlr_test_gsm_ciph, a hacky unit test fakes a situation where a CM2 is missing during proc_arq_fsm and proves that that code path works, even though the practical relevance is currently zero. It would only become interesting if ciphering algorithms A5/4 and higher became relevant, because support of those would be indicated in Classmark 3, which would always require a Classmark Request. Related: OS#3043 Depends: I4a2e1d3923e33912579c4180aa1ff8e8f5abb7e7 (libosmocore) Change-Id: I73c7cb6a86624695bd9c0f59abb72e2fdc655131 --- include/osmocom/msc/a_iface.h | 2 + include/osmocom/msc/gsm_data.h | 7 + include/osmocom/msc/osmo_msc.h | 6 + src/libmsc/a_iface.c | 10 + src/libmsc/gsm_04_08.c | 134 ++-- src/libmsc/osmo_msc.c | 4 + src/libmsc/subscr_conn.c | 74 +- tests/msc_vlr/Makefile.am | 1 + tests/msc_vlr/msc_vlr_test_gsm_ciph.c | 405 +++++++++- tests/msc_vlr/msc_vlr_test_gsm_ciph.err | 927 +++++++++++++++++++++- tests/msc_vlr/msc_vlr_test_ms_timeout.c | 70 ++ tests/msc_vlr/msc_vlr_test_ms_timeout.err | 130 +++ tests/msc_vlr/msc_vlr_tests.c | 61 +- tests/msc_vlr/msc_vlr_tests.h | 1 + 14 files changed, 1757 insertions(+), 75 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; - expect_bssap_clear(); 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("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_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,98 @@ 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 -DREF VLR subscr IMSI:901700000004620 usage decreases to: 1 +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 +2426,827 @@ 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 +- 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 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 +--- +- 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 #include #include +#include #if BUILD_IU #include @@ -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);