From a99b42709a09b1b822da0e431bf3308da7b7a295 Mon Sep 17 00:00:00 2001 From: Neels Hofmeyr Date: Tue, 21 Nov 2017 17:13:23 +0100 Subject: add msc_vlr_test_call to reproduce a sanitizer error On MT call, there is a bug in CC conn use which leads to an early free and use-after-free. Add msc_vlr_test_call to show both MO and MT call legs separately and reproduce the failure. It is visible in a sanitizer build (on debian 9). A subsequent patch will fix the bug: If0659a878deb383ed0300217e2c41c8c79b2b6a5 Related: OS#2672 Change-Id: I6c3ca0c660388b1e2c82df17ec540c846201b0c7 --- tests/msc_vlr/Makefile.am | 11 + tests/msc_vlr/msc_vlr_test_call.c | 341 ++++++++++++++++++ tests/msc_vlr/msc_vlr_test_call.err | 700 ++++++++++++++++++++++++++++++++++++ tests/msc_vlr/msc_vlr_test_call.ok | 1 + tests/msc_vlr/msc_vlr_tests.c | 58 ++- tests/msc_vlr/msc_vlr_tests.h | 17 + tests/testsuite.at | 7 + 7 files changed, 1131 insertions(+), 4 deletions(-) create mode 100644 tests/msc_vlr/msc_vlr_test_call.c create mode 100644 tests/msc_vlr/msc_vlr_test_call.err create mode 100644 tests/msc_vlr/msc_vlr_test_call.ok (limited to 'tests') diff --git a/tests/msc_vlr/Makefile.am b/tests/msc_vlr/Makefile.am index 7fc9212bb..8bbe6cba2 100644 --- a/tests/msc_vlr/Makefile.am +++ b/tests/msc_vlr/Makefile.am @@ -31,6 +31,8 @@ AM_LDFLAGS = \ -Wl,--wrap=msc_stop_paging \ -Wl,--wrap=gsm340_gen_scts \ -Wl,--wrap=RAND_bytes \ + -Wl,--wrap=msc_call_assignment \ + -Wl,--wrap=msc_call_release \ $(NULL) LDADD = \ @@ -75,6 +77,8 @@ EXTRA_DIST = \ msc_vlr_test_ms_timeout.err \ msc_vlr_test_reject_concurrency.ok \ msc_vlr_test_reject_concurrency.err \ + msc_vlr_test_call.ok \ + msc_vlr_test_call.err \ msc_vlr_test_rest.ok \ msc_vlr_test_rest.err \ $(NULL) @@ -89,6 +93,7 @@ noinst_PROGRAMS = \ msc_vlr_test_hlr_timeout \ msc_vlr_test_ms_timeout \ msc_vlr_test_reject_concurrency \ + msc_vlr_test_call \ msc_vlr_test_rest \ $(NULL) @@ -137,6 +142,11 @@ msc_vlr_test_reject_concurrency_SOURCES = \ msc_vlr_tests.c \ $(NULL) +msc_vlr_test_call_SOURCES = \ + msc_vlr_test_call.c \ + msc_vlr_tests.c \ + $(NULL) + msc_vlr_test_rest_SOURCES = \ msc_vlr_test_rest.c \ msc_vlr_tests.c \ @@ -153,4 +163,5 @@ update_exp: $(builddir)/msc_vlr_test_hlr_timeout >$(srcdir)/msc_vlr_test_hlr_timeout.ok 2>$(srcdir)/msc_vlr_test_hlr_timeout.err $(builddir)/msc_vlr_test_ms_timeout >$(srcdir)/msc_vlr_test_ms_timeout.ok 2>$(srcdir)/msc_vlr_test_ms_timeout.err $(builddir)/msc_vlr_test_reject_concurrency >$(srcdir)/msc_vlr_test_reject_concurrency.ok 2>$(srcdir)/msc_vlr_test_reject_concurrency.err + $(builddir)/msc_vlr_test_call >$(srcdir)/msc_vlr_test_call.ok 2>$(srcdir)/msc_vlr_test_call.err $(builddir)/msc_vlr_test_rest >$(srcdir)/msc_vlr_test_rest.ok 2>$(srcdir)/msc_vlr_test_rest.err diff --git a/tests/msc_vlr/msc_vlr_test_call.c b/tests/msc_vlr/msc_vlr_test_call.c new file mode 100644 index 000000000..cc120c8c4 --- /dev/null +++ b/tests/msc_vlr/msc_vlr_test_call.c @@ -0,0 +1,341 @@ +/* Osmocom MSC+VLR end-to-end tests */ + +/* (C) 2017 by sysmocom - s.f.m.c. GmbH + * + * All Rights Reserved + * + * Author: Neels Hofmeyr + * + * This program is free software; you can redistribute it and/or modify + * it under the terms of the GNU Affero General Public License as published by + * the Free Software Foundation; either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU Affero General Public License for more details. + * + * You should have received a copy of the GNU Affero General Public License + * along with this program. If not, see . + * + */ + +#include "msc_vlr_tests.h" + +#include + +void mncc_sends_to_cc(uint32_t msg_type, struct gsm_mncc *mncc) +{ + mncc->msg_type = msg_type; + mncc_tx_to_cc(net, msg_type, mncc); +} + +#define IMSI "901700000010650" + +static void standard_lu() +{ + struct vlr_subscr *vsub; + + net->authentication_required = true; + net->vlr->cfg.assign_tmsi = true; + rx_from_ran = RAN_UTRAN_IU; + + btw("Location Update request causes a GSUP Send Auth Info request to HLR"); + lu_result_sent = RES_NONE; + gsup_expect_tx("080108" "09710000000156f0"); + ms_sends_msg("0508" /* MM LU */ + "7" /* ciph key seq: no key available */ + "0" /* LU type: normal */ + "09f107" "0017" /* LAI, LAC */ + "57" /* classmark 1: R99, early classmark, no power lvl */ + "089910070000106005" /* IMSI */ + "3303575886" /* classmark 2 */ + ); + OSMO_ASSERT(gsup_tx_confirmed); + VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d"); + + btw("from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS"); + /* based on auc_3g: + * K = 'EB215756028D60E3275E613320AEC880', + * OPC = 'FB2A3D1B360F599ABAB99DB8669F8308' + * SQN = 0 + */ + auth_request_sent = false; + auth_request_expect_rand = "39fa2f4e3d523d8619a73b4f65c3e14d"; + auth_request_expect_autn = "8704f5ba55f30000d2ee44b22c8ea919"; + gsup_rx("0a" + /* imsi */ + "0108" "09710000000156f0" + /* 5 auth vectors... */ + /* TL TL rand */ + "0362" "2010" "39fa2f4e3d523d8619a73b4f65c3e14d" + /* TL sres TL kc */ + "2104" "9b36efdf" "2208" "059a4f668f6fbe39" + /* TL 3G IK */ + "2310" "27497388b6cb044648f396aa155b95ef" + /* TL 3G CK */ + "2410" "f64735036e5871319c679f4742a75ea1" + /* TL AUTN */ + "2510" "8704f5ba55f30000d2ee44b22c8ea919" + /* TL RES */ + "2708" "e229c19e791f2e41" + /* TL TL rand */ + "0362" "2010" "c187a53a5e6b9d573cac7c74451fd46d" + "2104" "85aa3130" "2208" "d3d50a000bf04f6e" + "2310" "1159ec926a50e98c034a6b7d7c9f418d" + "2410" "df3a03d9ca5335641efc8e36d76cd20b" + "2510" "1843a645b98d00005b2d666af46c45d9" + "2708" "7db47cf7f81e4dc7" + "0362" "2010" "efa9c29a9742148d5c9070348716e1bb" + "2104" "69d5f9fb" "2208" "3df176f0c29f1a3d" + "2310" "eb50e770ddcc3060101d2f43b6c2b884" + "2410" "76542abce5ff9345b0e8947f4c6e019c" + "2510" "f9375e6d41e1000096e7fe4ff1c27e39" + "2708" "706f996719ba609c" + "0362" "2010" "f023d5a3b24726e0631b64b3840f8253" + "2104" "d570c03f" "2208" "ec011be8919883d6" + "2310" "c4e58af4ba43f3bcd904e16984f086d7" + "2410" "0593f65e752e5cb7f473862bda05aa0a" + "2510" "541ff1f077270000c5ea00d658bc7e9a" + "2708" "3fd26072eaa2a04d" + "0362" "2010" "2f8f90c780d6a9c0c53da7ac57b6707e" + "2104" "b072446f220823f39f9f425ad6e6" + "2310" "65af0527fda95b0dc5ae4aa515cdf32f" + "2410" "537c3b35a3b13b08d08eeb28098f45cc" + "2510" "4bf4e564f75300009bc796706bc65744" + "2708" "0edb0eadbea94ac2", + NULL); + VERBOSE_ASSERT(auth_request_sent, == true, "%d"); + VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d"); + + btw("MS sends Authen Response, VLR accepts and sends SecurityModeControl"); + cipher_mode_cmd_sent = false; + ms_sends_msg("0554" "e229c19e" "2104" "791f2e41"); + VERBOSE_ASSERT(cipher_mode_cmd_sent, == true, "%d"); + VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d"); + + btw("MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR"); + gsup_expect_tx("04010809710000000156f0"); + ms_sends_security_mode_complete(); + VERBOSE_ASSERT(gsup_tx_confirmed, == true, "%d"); + VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d"); + + btw("HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT"); + gsup_rx("10010809710000000156f00804032443f2", + "12010809710000000156f0"); + VERBOSE_ASSERT(lu_result_sent, == RES_NONE, "%d"); + + btw("HLR also sends GSUP _UPDATE_LOCATION_RESULT"); + gsup_rx("06010809710000000156f0", NULL); + + VERBOSE_ASSERT(lu_result_sent, == RES_ACCEPT, "%d"); + + btw("a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl"); + EXPECT_CONN_COUNT(1); + EXPECT_ACCEPTED(false); + + btw("MS sends TMSI Realloc Complete"); + iu_release_expected = true; + iu_release_sent = false; + ms_sends_msg("055b"); + VERBOSE_ASSERT(iu_release_sent, == true, "%d"); \ + + btw("LU was successful, and the conn has already been closed"); + EXPECT_CONN_COUNT(0); + + vsub = vlr_subscr_find_by_imsi(net->vlr, IMSI); + VERBOSE_ASSERT(vsub != NULL, == true, "%d"); + VERBOSE_ASSERT(strcmp(vsub->imsi, IMSI), == 0, "%d"); + VERBOSE_ASSERT(vsub->lac, == 23, "%u"); + vlr_subscr_put(vsub); +} + +void test_call_mo() +{ + struct gsm_mncc mncc = { + .imsi = IMSI, + }; + + comment_start(); + + fake_time_start(); + + standard_lu(); + + BTW("after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector"); + auth_request_sent = false; + auth_request_expect_rand = "c187a53a5e6b9d573cac7c74451fd46d"; + auth_request_expect_autn = "1843a645b98d00005b2d666af46c45d9"; + cm_service_result_sent = RES_NONE; + ms_sends_msg("052478" + "03575886" /* classmark 2 */ + "089910070000106005" /* IMSI */); + OSMO_ASSERT(g_conn); + OSMO_ASSERT(g_conn->conn_fsm); + OSMO_ASSERT(g_conn->vsub); + VERBOSE_ASSERT(cm_service_result_sent, == RES_NONE, "%d"); + VERBOSE_ASSERT(auth_request_sent, == true, "%d"); + + btw("needs auth, not yet accepted"); + EXPECT_ACCEPTED(false); + + /* On UTRAN */ + btw("MS sends Authen Response, VLR accepts and sends SecurityModeControl"); + cipher_mode_cmd_sent = false; + ms_sends_msg("0554" "7db47cf7" "2104" "f81e4dc7"); /* 2nd vector's res, s.a. */ + VERBOSE_ASSERT(cipher_mode_cmd_sent, == true, "%d"); + VERBOSE_ASSERT(cm_service_result_sent, == RES_NONE, "%d"); + + btw("MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept"); + ms_sends_security_mode_complete(); + VERBOSE_ASSERT(cm_service_result_sent, == RES_NONE, "%d"); + + BTW("a call is initiated"); + + btw("SETUP gets forwarded to MNCC"); + cc_to_mncc_expect_tx(IMSI, MNCC_SETUP_IND); + ms_sends_msg("0385" /* CC, seq = 2 -> 0x80 | CC Setup = 0x5 */ + "0406600402000581" /* Bearer Capability */ + "5e038121f3" /* Called Number BCD */ + "15020100" /* CC Capabilities */ + "4008" /* Supported Codec List */ + "04026000" /* UMTS: AMR 2 | AMR */ + "00021f00" /* GSM: HR AMR | FR AMR | GSM EFR | GSM HR | GSM FR */ + ); + OSMO_ASSERT(cc_to_mncc_tx_confirmed); + mncc.callref = cc_to_mncc_tx_got_callref; + + btw("MNCC says that's fine"); + dtap_expect_tx("8302" /* CC: Call Proceeding */); + mncc_sends_to_cc(MNCC_CALL_PROC_REQ, &mncc); + OSMO_ASSERT(dtap_tx_confirmed); + + fake_time_passes(1, 23); + + btw("The other call leg got established (not shown here), MNCC tells us so"); + dtap_expect_tx("8301" /* CC: Call Alerting */); + mncc_sends_to_cc(MNCC_ALERT_REQ, &mncc); + OSMO_ASSERT(dtap_tx_confirmed); + + dtap_expect_tx("8307" /* CC: Connect */); + mncc_sends_to_cc(MNCC_SETUP_RSP, &mncc); + OSMO_ASSERT(dtap_tx_confirmed); + + fake_time_passes(1, 23); + + cc_to_mncc_expect_tx("", MNCC_SETUP_COMPL_IND); + ms_sends_msg("03cf" /* CC: Connect Acknowledge */); + OSMO_ASSERT(cc_to_mncc_tx_confirmed); + + BTW("RTP stream goes ahead, not shown here."); + fake_time_passes(123, 45); + + BTW("Call ends"); + cc_to_mncc_expect_tx("", MNCC_DISC_IND); + ms_sends_msg("032502e090" /* CC: Disconnect, cause: Normal Call Clearing */); + OSMO_ASSERT(cc_to_mncc_tx_confirmed); + + dtap_expect_tx("832d" /* CC: Release */); + mncc_sends_to_cc(MNCC_REL_REQ, &mncc); + OSMO_ASSERT(dtap_tx_confirmed); + + cc_to_mncc_expect_tx("", MNCC_REL_CNF); + expect_iu_release(); + ms_sends_msg("036a" /* CC: Release Complete */); + OSMO_ASSERT(cc_to_mncc_tx_confirmed); + OSMO_ASSERT(iu_release_sent); + + EXPECT_CONN_COUNT(0); + clear_vlr(); + comment_end(); +} + +void test_call_mt() +{ + struct gsm_mncc mncc = { + .imsi = IMSI, + .callref = 0x423, + }; + + comment_start(); + + fake_time_start(); + + standard_lu(); + + BTW("after a while, MNCC asks us to setup a call, causing Paging"); + + paging_expect_imsi(IMSI); + paging_sent = false; + mncc_sends_to_cc(MNCC_SETUP_REQ, &mncc); + + VERBOSE_ASSERT(paging_sent, == true, "%d"); + VERBOSE_ASSERT(paging_stopped, == false, "%d"); + + btw("MS replies with Paging Response, and VLR sends Auth Request"); + auth_request_sent = false; + auth_request_expect_rand = "c187a53a5e6b9d573cac7c74451fd46d"; + auth_request_expect_autn = "1843a645b98d00005b2d666af46c45d9"; + ms_sends_msg("062707" + "03575886" /* classmark 2 */ + "089910070000106005" /* IMSI */); + VERBOSE_ASSERT(auth_request_sent, == true, "%d"); + + btw("MS sends Authen Response, VLR accepts and sends SecurityModeControl"); + cipher_mode_cmd_sent = false; + ms_sends_msg("0554" "7db47cf7" "2104" "f81e4dc7"); /* 2nd vector's res, s.a. */ + VERBOSE_ASSERT(cipher_mode_cmd_sent, == true, "%d"); + + btw("MS sends SecurityModeControl acceptance, VLR accepts, sends CC Setup"); + dtap_expect_tx("0305" /* CC: Setup */); + ms_sends_security_mode_complete(); + VERBOSE_ASSERT(paging_stopped, == true, "%d"); + + cc_to_mncc_expect_tx(IMSI, MNCC_CALL_CONF_IND); + ms_sends_msg("8348" /* CC: Call Confirmed */ + "0406600402000581" /* Bearer Capability */ + "15020100" /* Call Control Capabilities */ + "40080402600400021f00" /* Supported Codec List */); + + fake_time_passes(1, 23); + + cc_to_mncc_expect_tx("", MNCC_ALERT_IND); + ms_sends_msg("8381" /* CC: Alerting */); + + fake_time_passes(1, 23); + + cc_to_mncc_expect_tx(IMSI, MNCC_SETUP_CNF); + ms_sends_msg("83c7" /* CC: Connect */); + + dtap_expect_tx("030f" /* CC: Connect Acknowledge */); + mncc_sends_to_cc(MNCC_SETUP_COMPL_REQ, &mncc); + + BTW("RTP stream goes ahead, not shown here."); + fake_time_passes(123, 45); + + BTW("Call ends"); + cc_to_mncc_expect_tx("", MNCC_DISC_IND); + ms_sends_msg("832502e090" /* CC: Disconnect, cause: Normal Call Clearing */); + OSMO_ASSERT(cc_to_mncc_tx_confirmed); + + dtap_expect_tx("032d" /* CC: Release */); + mncc_sends_to_cc(MNCC_REL_REQ, &mncc); + OSMO_ASSERT(dtap_tx_confirmed); + + cc_to_mncc_expect_tx("", MNCC_REL_CNF); + expect_iu_release(); + ms_sends_msg("836a" /* CC: Release Complete */); + OSMO_ASSERT(cc_to_mncc_tx_confirmed); + OSMO_ASSERT(iu_release_sent); + + EXPECT_CONN_COUNT(0); + clear_vlr(); + comment_end(); +} + +msc_vlr_test_func_t msc_vlr_tests[] = { + test_call_mo, + test_call_mt, + NULL +}; diff --git a/tests/msc_vlr/msc_vlr_test_call.err b/tests/msc_vlr/msc_vlr_test_call.err new file mode 100644 index 000000000..6fd928853 --- /dev/null +++ b/tests/msc_vlr/msc_vlr_test_call.err @@ -0,0 +1,700 @@ +===== test_call_mo +- Total time passed: 0.000000 s +- Location Update request causes a GSUP Send Auth Info request to HLR + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST + new conn +DREF unknown: MSC conn use + compl_l3 == 1 (0x1) +DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) +DREF unknown: MSC conn use + fsm == 2 (0x5) +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW +DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL +DMM LU/new-LAC: 23/23 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650) +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA +DREF VLR subscr unknown usage increases to: 1 +DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650 +DVLR New subscr, IMSI: 901700000010650 +DREF VLR subscr IMSI:901700000010650 usage increases to: 2 +DREF VLR subscr IMSI:901700000010650 usage decreases to: 1 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1() +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START +DVLR GSUP tx: 08010809710000000156f0 +GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW) +DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4) + lu_result_sent == 0 +- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS +<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2 +DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2 +DREF VLR subscr IMSI:901700000010650 usage increases to: 2 +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK +DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 +- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and... +- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d +- ...autn=8704f5ba55f30000d2ee44b22c8ea919 +- ...expecting res=e229c19e791f2e41 +DREF VLR subscr IMSI:901700000010650 usage decreases to: 1 +<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0 + auth_request_sent == 1 + lu_result_sent == 0 +- MS sends Authen Response, VLR accepts and sends SecurityModeControl + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP +DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14) +DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = e229c19e791f2e41) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP +DVLR SUBSCR(IMSI:901700000010650) received res: e2 29 c1 9e 79 1f 2e 41 +DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth() +- sending SecurityModeControl for IMSI:901700000010650 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH +DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW) +DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4) + cipher_mode_cmd_sent == 1 + lu_result_sent == 0 +- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR +DMM <- SECURITY MODE COMPLETE IMSI:901700000010650 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph() +DIUCS IMSI:901700000010650: tx CommonID 901700000010650 +- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650) +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4() +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650) +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START +DVLR GSUP tx: 04010809710000000156f0 +GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0 +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA + gsup_tx_confirmed == 1 + lu_result_sent == 0 +- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT +<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2 +DVLR GSUP rx 17: 10010809710000000156f00804032443f2 +DREF VLR subscr IMSI:901700000010650 usage increases to: 2 +DVLR IMSI:901700000010650 has MSISDN:42342 +DVLR GSUP tx: 12010809710000000156f0 +GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0 +DREF VLR subscr MSISDN:42342 usage decreases to: 1 +<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0 + lu_result_sent == 0 +- HLR also sends GSUP _UPDATE_LOCATION_RESULT +<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0 +DVLR GSUP rx 11: 06010809710000000156f0 +DREF VLR subscr MSISDN:42342 usage increases to: 2 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650) +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650) +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650) +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650) +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi() +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF +- sending LU Accept for MSISDN:42342, with TMSI 0x03020100 +DREF VLR subscr MSISDN:42342 usage decreases to: 1 +<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0 + lu_result_sent == 1 +- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl + llist_count(&net->subscr_conns) == 1 +msc_subscr_conn_is_accepted() == false +- MS sends TMSI Realloc Complete + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL +DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b) +DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK +DREF VLR subscr MSISDN:42342 usage increases to: 2 +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650) +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650) +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated +DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event. +- Iu Release --RAN_UTRAN_IU--> MS +DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2) +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated +DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0) +DRLL subscr MSISDN:42342: Freeing subscriber connection +DREF VLR subscr MSISDN:42342 usage decreases to: 1 + iu_release_sent == 1 +- LU was successful, and the conn has already been closed + llist_count(&net->subscr_conns) == 0 +DREF VLR subscr MSISDN:42342 usage increases to: 2 + vsub != NULL == 1 + strcmp(vsub->imsi, IMSI) == 0 + vsub->lac == 23 +DREF VLR subscr MSISDN:42342 usage decreases to: 1 +--- +- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_CM_SERV_REQ + new conn +DREF unknown: MSC conn use + compl_l3 == 1 (0x1) +DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24) +DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650 +DREF unknown: MSC conn use + fsm == 2 (0x5) +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START +DREF VLR subscr MSISDN:42342 usage increases to: 2 +DREF VLR subscr MSISDN:42342 usage increases to: 3 +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 +- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and... +- ...rand=c187a53a5e6b9d573cac7c74451fd46d +- ...autn=1843a645b98d00005b2d666af46c45d9 +- ...expecting res=7db47cf7f81e4dc7 +DREF VLR subscr MSISDN:42342 usage decreases to: 2 +DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW) +DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4) + cm_service_result_sent == 0 + auth_request_sent == 1 +- needs auth, not yet accepted +msc_subscr_conn_is_accepted() == false +- MS sends Authen Response, VLR accepts and sends SecurityModeControl + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP +DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14) +DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP +DVLR SUBSCR(MSISDN:42342) received res: 7d b4 7c f7 f8 1e 4d c7 +DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2() +- sending SecurityModeControl for MSISDN:42342 +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH +DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW) +DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4) + cipher_mode_cmd_sent == 1 + cm_service_result_sent == 0 +- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept +DMM <- SECURITY MODE COMPLETE MSISDN:42342 +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph() +DIUCS MSISDN:42342: tx CommonID 901700000010650 +- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr() +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres() +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace() +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei() +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request + cm_service_result_sent == 0 +--- +- a call is initiated +- SETUP gets forwarded to MNCC + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_SETUP +DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5) +DREF VLR subscr MSISDN:42342 usage increases to: 3 +DREF MSISDN:42342: MSC conn use + trans_cc == 3 (0xe) +DMM MSISDN:42342: rx msg GSM48_MT_CC_SETUP: received_cm_service_request changes to false +DCC Subscriber MSISDN:42342 (42342) sends SETUP to 123 +DMNCC transmit message MNCC_SETUP_IND + MSC --> MNCC: callref 0x80000001: MNCC_SETUP_IND +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC +DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc) +- MNCC says that's fine +DMNCC receive message MNCC_CALL_PROC_REQ +DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU +- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CALL_PROC: 8302 +- DTAP matches expected message + MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x80000001 +- Total time passed: 1.000023 s +- The other call leg got established (not shown here), MNCC tells us so +DMNCC receive message MNCC_ALERT_REQ +DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU +- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_ALERTING: 8301 +- DTAP matches expected message +DMNCC receive message MNCC_SETUP_RSP +DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU +- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CONNECT: 8307 +- DTAP matches expected message +- Total time passed: 2.000046 s + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_CONNECT_ACK +DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe) +DRLL Dispatching 04.08 message GSM48_MT_CC_CONNECT_ACK (0x3:0xf) +DMNCC transmit message MNCC_SETUP_COMPL_IND + MSC --> MNCC: callref 0x80000001: MNCC_SETUP_COMPL_IND +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC +DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc) +--- +- RTP stream goes ahead, not shown here. +- Total time passed: 125.000091 s +--- +- Call ends + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_DISCONNECT +DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe) +DRLL Dispatching 04.08 message GSM48_MT_CC_DISCONNECT (0x3:0x25) +DMNCC transmit message MNCC_DISC_IND + MSC --> MNCC: callref 0x80000001: MNCC_DISC_IND +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC +DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc) +DMNCC receive message MNCC_REL_REQ +DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU +- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d +- DTAP matches expected message + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_RELEASE_COMPL +DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe) +DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a) +DMNCC transmit message MNCC_REL_CNF + MSC --> MNCC: callref 0x80000001: MNCC_REL_CNF + MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x0 +DREF VLR subscr MSISDN:42342 usage decreases to: 2 +DREF MSISDN:42342: MSC conn use - trans_cc == 2 (0x6) +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated +DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event. +- Iu Release --RAN_UTRAN_IU--> MS +DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2) +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated +DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0) +DRLL subscr MSISDN:42342: Freeing subscriber connection +DREF VLR subscr MSISDN:42342 usage decreases to: 1 + llist_count(&net->subscr_conns) == 0 +DREF freeing VLR subscr MSISDN:42342 +===== test_call_mo: SUCCESS + +full talloc report on 'msgb' (total 0 bytes in 1 blocks) +talloc_total_blocks(tall_bsc_ctx) == 9 + +===== test_call_mt +- Total time passed: 0.000000 s +- Location Update request causes a GSUP Send Auth Info request to HLR + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST + new conn +DREF unknown: MSC conn use + compl_l3 == 1 (0x1) +DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) +DREF unknown: MSC conn use + fsm == 2 (0x5) +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW +DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL +DMM LU/new-LAC: 23/23 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650) +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA +DREF VLR subscr unknown usage increases to: 1 +DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650 +DVLR New subscr, IMSI: 901700000010650 +DREF VLR subscr IMSI:901700000010650 usage increases to: 2 +DREF VLR subscr IMSI:901700000010650 usage decreases to: 1 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1() +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START +DVLR GSUP tx: 08010809710000000156f0 +GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW) +DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4) + lu_result_sent == 0 +- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS +<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2 +DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2 +DREF VLR subscr IMSI:901700000010650 usage increases to: 2 +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK +DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 +- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and... +- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d +- ...autn=8704f5ba55f30000d2ee44b22c8ea919 +- ...expecting res=e229c19e791f2e41 +DREF VLR subscr IMSI:901700000010650 usage decreases to: 1 +<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0 + auth_request_sent == 1 + lu_result_sent == 0 +- MS sends Authen Response, VLR accepts and sends SecurityModeControl + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP +DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14) +DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = e229c19e791f2e41) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP +DVLR SUBSCR(IMSI:901700000010650) received res: e2 29 c1 9e 79 1f 2e 41 +DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth() +- sending SecurityModeControl for IMSI:901700000010650 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH +DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW) +DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4) + cipher_mode_cmd_sent == 1 + lu_result_sent == 0 +- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR +DMM <- SECURITY MODE COMPLETE IMSI:901700000010650 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph() +DIUCS IMSI:901700000010650: tx CommonID 901700000010650 +- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650) +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4() +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650) +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START +DVLR GSUP tx: 04010809710000000156f0 +GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0 +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA + gsup_tx_confirmed == 1 + lu_result_sent == 0 +- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT +<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2 +DVLR GSUP rx 17: 10010809710000000156f00804032443f2 +DREF VLR subscr IMSI:901700000010650 usage increases to: 2 +DVLR IMSI:901700000010650 has MSISDN:42342 +DVLR GSUP tx: 12010809710000000156f0 +GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0 +DREF VLR subscr MSISDN:42342 usage decreases to: 1 +<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0 + lu_result_sent == 0 +- HLR also sends GSUP _UPDATE_LOCATION_RESULT +<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0 +DVLR GSUP rx 11: 06010809710000000156f0 +DREF VLR subscr MSISDN:42342 usage increases to: 2 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650) +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance +DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650) +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650) +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650) +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance +DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi() +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF +- sending LU Accept for MSISDN:42342, with TMSI 0x03020100 +DREF VLR subscr MSISDN:42342 usage decreases to: 1 +<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0 + lu_result_sent == 1 +- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl + llist_count(&net->subscr_conns) == 1 +msc_subscr_conn_is_accepted() == false +- MS sends TMSI Realloc Complete + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL +DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b) +DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342 +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK +DREF VLR subscr MSISDN:42342 usage increases to: 2 +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650) +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance +DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650) +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance +DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated +DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event. +- Iu Release --RAN_UTRAN_IU--> MS +DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2) +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated +DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0) +DRLL subscr MSISDN:42342: Freeing subscriber connection +DREF VLR subscr MSISDN:42342 usage decreases to: 1 + iu_release_sent == 1 +- LU was successful, and the conn has already been closed + llist_count(&net->subscr_conns) == 0 +DREF VLR subscr MSISDN:42342 usage increases to: 2 + vsub != NULL == 1 + strcmp(vsub->imsi, IMSI) == 0 + vsub->lac == 23 +DREF VLR subscr MSISDN:42342 usage decreases to: 1 +--- +- after a while, MNCC asks us to setup a call, causing Paging +DMNCC receive message MNCC_SETUP_REQ +DREF VLR subscr MSISDN:42342 usage increases to: 2 +DREF VLR subscr MSISDN:42342 usage increases to: 3 +DMM Subscriber MSISDN:42342 not paged yet, start paging. + RAN_UTRAN_IU sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23 + strcmp(paging_expecting_imsi, imsi) == 0 +DREF VLR subscr MSISDN:42342 usage increases to: 4 +DREF VLR subscr MSISDN:42342 usage decreases to: 3 + paging_sent == 1 + paging_stopped == 0 +- MS replies with Paging Response, and VLR sends Auth Request + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_RR_PAG_RESP + new conn +DREF unknown: MSC conn use + compl_l3 == 1 (0x1) +DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27) +DRR PAGING RESPONSE: MI(IMSI)=901700000010650 +DREF unknown: MSC conn use + fsm == 2 (0x5) +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START +DREF VLR subscr MSISDN:42342 usage increases to: 4 +DREF VLR subscr MSISDN:42342 usage increases to: 5 +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 +- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and... +- ...rand=c187a53a5e6b9d573cac7c74451fd46d +- ...autn=1843a645b98d00005b2d666af46c45d9 +- ...expecting res=7db47cf7f81e4dc7 +DREF VLR subscr MSISDN:42342 usage decreases to: 4 +DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW) +DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4) + auth_request_sent == 1 +- MS sends Authen Response, VLR accepts and sends SecurityModeControl + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP +DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14) +DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP +DVLR SUBSCR(MSISDN:42342) received res: 7d b4 7c f7 f8 1e 4d c7 +DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650) +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance +DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2() +- sending SecurityModeControl for MSISDN:42342 +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH +DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW) +DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4) + cipher_mode_cmd_sent == 1 +- MS sends SecurityModeControl acceptance, VLR accepts, sends CC Setup +DMM <- SECURITY MODE COMPLETE MSISDN:42342 +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph() +DIUCS MSISDN:42342: tx CommonID 901700000010650 +- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr() +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres() +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace() +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei() +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED +DPAG Paging success for MSISDN:42342 (event=0) +DPAG Calling paging cbfn. +DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU +- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_SETUP: 0305 +- DTAP matches expected message +DREF VLR subscr MSISDN:42342 usage decreases to: 3 +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_CC + paging_stopped == 1 + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_CALL_CONF +DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_CC_CALL_CONF (0x3:0x8) + MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x423 +DMNCC transmit message MNCC_CALL_CONF_IND + MSC --> MNCC: callref 0x423: MNCC_CALL_CONF_IND +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC +DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4) +- Total time passed: 1.000023 s + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_ALERTING +DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_CC_ALERTING (0x3:0x1) +DMNCC transmit message MNCC_ALERT_IND + MSC --> MNCC: callref 0x423: MNCC_ALERT_IND +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC +DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4) +- Total time passed: 2.000046 s + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_CONNECT +DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_CC_CONNECT (0x3:0x7) +DMNCC transmit message MNCC_SETUP_CNF + MSC --> MNCC: callref 0x423: MNCC_SETUP_CNF +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC +DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4) +DMNCC receive message MNCC_SETUP_COMPL_REQ +DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU +- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CONNECT_ACK: 030f +- DTAP matches expected message +--- +- RTP stream goes ahead, not shown here. +- Total time passed: 125.000091 s +--- +- Call ends + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_DISCONNECT +DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_CC_DISCONNECT (0x3:0x25) +DMNCC transmit message MNCC_DISC_IND + MSC --> MNCC: callref 0x423: MNCC_DISC_IND +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC +DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4) +DMNCC receive message MNCC_REL_REQ +DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU +- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 032d +- DTAP matches expected message + MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_RELEASE_COMPL +DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6) +DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a) +DMNCC transmit message MNCC_REL_CNF + MSC --> MNCC: callref 0x423: MNCC_REL_CNF + MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x0 +DREF VLR subscr MSISDN:42342 usage decreases to: 2 +DREF MSISDN:42342: MSC conn use error: freeing an unused token: trans_cc +DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x6) +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650) +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance +DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated +DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event. +- Iu Release --RAN_UTRAN_IU--> MS +DREF MSISDN:42342: MSC conn use - fsm == 0 (0x2) +DRLL subscr MSISDN:42342: Freeing subscriber connection +DREF VLR subscr MSISDN:42342 usage decreases to: 1 +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance +DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated +DREF unknown: MSC conn use - dtap failed: is already 0 + llist_count(&net->subscr_conns) == 0 +DREF freeing VLR subscr MSISDN:42342 +===== test_call_mt: SUCCESS + +full talloc report on 'msgb' (total 0 bytes in 1 blocks) +talloc_total_blocks(tall_bsc_ctx) == 9 + +full talloc report on 'msgb' (total 0 bytes in 1 blocks) +talloc_total_blocks(tall_bsc_ctx) == 9 + diff --git a/tests/msc_vlr/msc_vlr_test_call.ok b/tests/msc_vlr/msc_vlr_test_call.ok new file mode 100644 index 000000000..a965a70ed --- /dev/null +++ b/tests/msc_vlr/msc_vlr_test_call.ok @@ -0,0 +1 @@ +Done diff --git a/tests/msc_vlr/msc_vlr_tests.c b/tests/msc_vlr/msc_vlr_tests.c index 550c5d842..dd7196c0f 100644 --- a/tests/msc_vlr/msc_vlr_tests.c +++ b/tests/msc_vlr/msc_vlr_tests.c @@ -34,6 +34,7 @@ #include #include #include +#include #if BUILD_IU #include @@ -69,6 +70,11 @@ bool iu_release_sent = false; bool bssap_clear_expected = false; bool bssap_clear_sent = false; +uint32_t cc_to_mncc_tx_expected_msg_type = 0; +const char *cc_to_mncc_tx_expected_imsi = NULL; +bool cc_to_mncc_tx_confirmed = false; +uint32_t cc_to_mncc_tx_got_callref = 0; + struct msgb *msgb_from_hex(const char *label, uint16_t size, const char *hex) { struct msgb *msg = msgb_alloc(size, label); @@ -377,7 +383,7 @@ static struct log_info_cat test_categories[] = { [DCC] = { .name = "DCC", .description = "Layer3 Call Control (CC)", - .enabled = 1, .loglevel = LOGL_NOTICE, + .enabled = 1, .loglevel = LOGL_INFO, }, [DMM] = { .name = "DMM", @@ -404,6 +410,11 @@ static struct log_info_cat test_categories[] = { .description = "Iu-CS Protocol", .enabled = 1, .loglevel = LOGL_DEBUG, }, + [DMNCC] = { + .name = "DMNCC", + .description = "MNCC API for Call Control application", + .enabled = 1, .loglevel = LOGL_DEBUG, + }, }; static struct log_info info = { @@ -413,9 +424,31 @@ static struct log_info info = { extern void *tall_bsc_ctx; -int fake_mncc_recv(struct gsm_network *net, struct msgb *msg) +int mncc_recv(struct gsm_network *net, struct msgb *msg) { - fprintf(stderr, "rx MNCC\n"); + struct gsm_mncc *mncc = (void*)msg->data; + log("MSC --> MNCC: callref 0x%x: %s", mncc->callref, + get_mncc_name(mncc->msg_type)); + + OSMO_ASSERT(cc_to_mncc_tx_expected_msg_type); + if (cc_to_mncc_tx_expected_msg_type != mncc->msg_type) { + log("Mismatch! Expected MNCC msg type: %s", + get_mncc_name(cc_to_mncc_tx_expected_msg_type)); + abort(); + } + + if (strcmp(cc_to_mncc_tx_expected_imsi, mncc->imsi)) { + log("Mismatch! Expected MNCC msg IMSI: '%s', got '%s'", + cc_to_mncc_tx_expected_imsi, + mncc->imsi); + abort(); + } + + cc_to_mncc_tx_confirmed = true; + cc_to_mncc_tx_got_callref = mncc->callref; + cc_to_mncc_tx_expected_imsi = NULL; + cc_to_mncc_tx_expected_msg_type = 0; + talloc_free(msg); return 0; } @@ -523,6 +556,23 @@ int __wrap_a_iface_tx_clear_cmd(struct gsm_subscriber_connection *conn) return 0; } +/* override, requires '-Wl,--wrap=msc_call_assignment' */ +int __real_msc_call_assignment(struct gsm_trans *trans); +int __wrap_msc_call_assignment(struct gsm_trans *trans) +{ + log("MS <--Call Assignment-- MSC: subscr=%s callref=0x%x", + vlr_subscr_name(trans->vsub), trans->callref); + return 0; +} + +/* override, requires '-Wl,--wrap=msc_call_release' */ +void __real_msc_call_release(struct gsm_trans *trans); +void __wrap_msc_call_release(struct gsm_trans *trans) +{ + log("MS <--Call Release-- MSC: subscr=%s callref=0x%x", + vlr_subscr_name(trans->vsub), trans->callref); +} + static int fake_vlr_tx_lu_acc(void *msc_conn_ref, uint32_t send_tmsi) { struct gsm_subscriber_connection *conn = msc_conn_ref; @@ -774,7 +824,7 @@ int main(int argc, char **argv) log_set_print_filename(osmo_stderr_target, _log_lines? 1 : 0); log_set_print_category(osmo_stderr_target, 1); - net = gsm_network_init(tall_bsc_ctx, 1, 1, fake_mncc_recv); + net = gsm_network_init(tall_bsc_ctx, 1, 1, mncc_recv); net->gsup_server_addr_str = talloc_strdup(net, "no_gsup_server"); net->gsup_server_port = 0; diff --git a/tests/msc_vlr/msc_vlr_tests.h b/tests/msc_vlr/msc_vlr_tests.h index 1cd391481..ee26ac40d 100644 --- a/tests/msc_vlr/msc_vlr_tests.h +++ b/tests/msc_vlr/msc_vlr_tests.h @@ -29,6 +29,7 @@ #include #include #include +#include extern bool _log_lines; #define _log(fmt, args...) do { \ @@ -84,6 +85,11 @@ extern bool iu_release_sent; extern bool bssap_clear_expected; extern bool bssap_clear_sent; +extern uint32_t cc_to_mncc_tx_expected_msg_type; +extern const char *cc_to_mncc_tx_expected_imsi; +extern bool cc_to_mncc_tx_confirmed; +extern uint32_t cc_to_mncc_tx_got_callref; + static inline void expect_iu_release() { iu_release_expected = true; @@ -169,6 +175,17 @@ void check_talloc(void *msgb_ctx, void *tall_bsc_ctx, int expected_blocks); gsup_tx_confirmed = false; \ } while (0) +#define cc_to_mncc_expect_tx(imsi, msg_type) do \ +{ \ + if (cc_to_mncc_tx_expected_msg_type) { \ + log("Previous expected MNCC tx was not confirmed!"); \ + OSMO_ASSERT(!cc_to_mncc_tx_expected_msg_type); \ + } \ + cc_to_mncc_tx_expected_imsi = imsi; \ + cc_to_mncc_tx_expected_msg_type = msg_type; \ + cc_to_mncc_tx_confirmed = false; \ +} while (0) + void fake_time_start(); /* as macro to get the test file's source line number */ diff --git a/tests/testsuite.at b/tests/testsuite.at index f0147e79b..5307899c8 100644 --- a/tests/testsuite.at +++ b/tests/testsuite.at @@ -79,6 +79,13 @@ cat $abs_srcdir/msc_vlr/msc_vlr_test_reject_concurrency.err > experr AT_CHECK([$abs_top_builddir/tests/msc_vlr/msc_vlr_test_reject_concurrency], [], [expout], [experr]) AT_CLEANUP +AT_SETUP([msc_vlr_test_call]) +AT_KEYWORDS([msc_vlr_test_call]) +cat $abs_srcdir/msc_vlr/msc_vlr_test_call.ok > expout +cat $abs_srcdir/msc_vlr/msc_vlr_test_call.err > experr +AT_CHECK([$abs_top_builddir/tests/msc_vlr/msc_vlr_test_call], [], [expout], [experr]) +AT_CLEANUP + AT_SETUP([msc_vlr_test_rest]) AT_KEYWORDS([msc_vlr_test_rest]) cat $abs_srcdir/msc_vlr/msc_vlr_test_rest.ok > expout -- cgit v1.2.3