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);