Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / 46c06e28c18241b586ecb5847daa6a5ab6b49b84 / . / tests / msc_vlr / msc_vlr_test_call.err
blob: d410d1a5268a42300257c790587077b18dcfd699 [file] [log] [blame]
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]2talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]3
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]4===== test_call_mo
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]5- Total time passed: 0.000000 s
6- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]7 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]8 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]9DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]10DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]11DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]12DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyr46c06e22019-01-04 17:42:05 +0100[diff] [blame^]13DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: LOCATION UPDATING REQUEST: MI=IMSI-901700000010650 LU-type=NORMAL
14DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: LU/new-LAC: 23/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]15DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]16DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: is child of RAN_conn(LU:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]17DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
18DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]19DREF VLR subscr unknown usage increases to: 1
20DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
21DVLR New subscr, IMSI: 901700000010650
22DREF VLR subscr IMSI:901700000010650 usage increases to: 2
23DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]24DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
25DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
26DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
27DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650)
28DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]29DVLR GSUP tx: 08010809710000000156f0
30GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]31DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]32DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
33DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]34DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]35DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
36DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]37 lu_result_sent == 0
38- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
39<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
40DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
41DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]42DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]43DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]44DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
45DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]46- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
47- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
48- ...autn=8704f5ba55f30000d2ee44b22c8ea919
49- ...expecting res=e229c19e791f2e41
50DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
51<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
52 auth_request_sent == 1
53 lu_result_sent == 0
54- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]55 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]56DREF IMSI:901700000010650: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]57DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100[diff] [blame]58DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]59DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100[diff] [blame]60DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]61DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]62DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]63DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
64DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
65DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650)
66DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
67DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
68DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
69DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
70DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100[diff] [blame]71DMM -> SECURITY MODE CONTROL IMSI:901700000010650
72- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
73- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]74DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]75DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]76DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
77DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100[diff] [blame]78 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]79 lu_result_sent == 0
80- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
81DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]82DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
83DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]84DIUCS IMSI:901700000010650: tx CommonID 901700000010650
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]85- Iu Common ID --UTRAN-Iu--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]86DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
87DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
88DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
89DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
90DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +0200[diff] [blame]91DVLR GSUP tx: 04010809710000000156f0280102
92GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]93DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]94 gsup_tx_confirmed == 1
95 lu_result_sent == 0
96- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
97<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
98DVLR GSUP rx 17: 10010809710000000156f00804032443f2
99DREF VLR subscr IMSI:901700000010650 usage increases to: 2
100DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]101DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]102DVLR GSUP tx: 12010809710000000156f0
103GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
104DREF VLR subscr MSISDN:42342 usage decreases to: 1
105<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
106 lu_result_sent == 0
107- HLR also sends GSUP _UPDATE_LOCATION_RESULT
108<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
109DVLR GSUP rx 11: 06010809710000000156f0
110DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]111DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
112DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
113DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
114DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
115DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
116DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
117DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
118DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
119DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
120DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
121DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
122DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
123DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]124DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
125DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
126DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]127- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
128DREF VLR subscr MSISDN:42342 usage decreases to: 1
129<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
130 lu_result_sent == 1
131- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]132 llist_count(&net->ran_conns) == 1
133ran_conn_is_accepted() == false
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]134- MS sends TMSI Realloc Complete
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]135 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]136DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]137DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
138DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]139DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
140DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]141DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]142DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
143DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
144DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
145DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
146DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
147DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
148DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]149DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
150DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
151DMM RAN_conn(LU:901700000010650){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_UNUSED
152DMM RAN_conn(LU:901700000010650){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]153DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]154DREF VLR subscr MSISDN:42342 usage increases to: 3
155DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]156- Iu Release --UTRAN-Iu--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]157DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]158 iu_release_sent == 1
159- LU was successful, and the conn has already been closed
160- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]161DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]162DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
163DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
164DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]165DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]166DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent RAN_conn(LU:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]167DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
168DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Freeing instance
169DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]170DRLL MSISDN:42342: Freeing RAN connection
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]171DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]172DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Freeing instance
173DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Deallocated
174 llist_count(&net->ran_conns) == 0
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]175DREF VLR subscr MSISDN:42342 usage increases to: 2
176 vsub != NULL == 1
177 strcmp(vsub->imsi, IMSI) == 0
Max33b6d0c2018-12-17 17:15:13 +0100[diff] [blame]178 LAC == 23
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]179DREF VLR subscr MSISDN:42342 usage decreases to: 1
180---
181- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]182 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]183 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]184DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]185DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]186DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr46c06e22019-01-04 17:42:05 +0100[diff] [blame^]187DMM RAN_conn{RAN_CONN_S_NEW}: Rx CM SERVICE REQUEST cm_service_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]188DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]189DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]190DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: is child of RAN_conn(CM_SERVICE_REQ:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]191DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
192DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]193DREF VLR subscr MSISDN:42342 usage increases to: 2
194DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]195DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
196DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
197DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
198DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
199DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
200DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
201DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]202- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
203- ...rand=c187a53a5e6b9d573cac7c74451fd46d
204- ...autn=1843a645b98d00005b2d666af46c45d9
205- ...expecting res=7db47cf7f81e4dc7
206DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]207DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
208DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]209DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]210DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
211DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]212 cm_service_result_sent == 0
213 auth_request_sent == 1
214- needs auth, not yet accepted
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]215ran_conn_is_accepted() == false
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]216- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]217 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]218DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]219DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100[diff] [blame]220DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]221DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100[diff] [blame]222DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]223DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]224DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]225DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
226DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
227DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
228DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
229DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
230DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]231DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
232DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100[diff] [blame]233DMM -> SECURITY MODE CONTROL MSISDN:42342
234- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
235- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]236DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]237DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]238DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
239DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100[diff] [blame]240 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]241 cm_service_result_sent == 0
242- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
243DMM <- SECURITY MODE COMPLETE MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]244DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
245DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]246DIUCS MSISDN:42342: tx CommonID 901700000010650
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]247- Iu Common ID --UTRAN-Iu--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]248DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
249DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
250DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
251DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]252DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]253DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]254DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]255DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]256DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]257DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
258DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_ACCEPTED}: ran_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]259 cm_service_result_sent == 0
260---
261- a call is initiated
262- SETUP gets forwarded to MNCC
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]263 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_SETUP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]264DREF MSISDN:42342: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]265DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]266DCC Unknown transaction ID 8, creating new trans.
267DCC (ti 08 sub MSISDN:42342 callref 80000001) New transaction
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]268DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]269DREF MSISDN:42342: MSC conn use + trans_cc == 3 (0x1a: dtap,cm_service,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]270DMM MSISDN:42342: rx msg GSM48_MT_CC_SETUP: received_cm_service_request changes to false
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]271DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x12: dtap,trans_cc)
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]272DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]273DCC (ti 08 sub MSISDN:42342) new state NULL -> INITIATED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]274DCC Subscriber MSISDN:42342 (42342) sends SETUP to 123
275DMNCC transmit message MNCC_SETUP_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]276DCC Sending 'MNCC_SETUP_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]277 MSC --> MNCC: callref 0x80000001: MNCC_SETUP_IND
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]278DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMMUNICATING
279DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]280DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]281- MNCC says that's fine
282DMNCC receive message MNCC_CALL_PROC_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]283DCC (sub 42342) stopping pending guard timer
284DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]285DCC (ti 08 sub 42342) Received 'MNCC_CALL_PROC_REQ' from MNCC in state 1 (INITIATED)
286DCC (ti 08 sub MSISDN:42342) new state INITIATED -> MO_CALL_PROC
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]287DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
288- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_CALL_PROC: 8302
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]289- DTAP matches expected message
290 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x80000001
291- Total time passed: 1.000023 s
292- The other call leg got established (not shown here), MNCC tells us so
293DMNCC receive message MNCC_ALERT_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]294DCC (sub 42342) stopping pending guard timer
295DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]296DCC (ti 08 sub 42342) Received 'MNCC_ALERT_REQ' from MNCC in state 3 (MO_CALL_PROC)
297DCC (ti 08 sub MSISDN:42342) new state MO_CALL_PROC -> CALL_DELIVERED
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]298DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
299- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_ALERTING: 8301
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]300- DTAP matches expected message
301DMNCC receive message MNCC_SETUP_RSP
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]302DCC (sub 42342) stopping pending guard timer
303DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]304DCC (ti 08 sub 42342) Received 'MNCC_SETUP_RSP' from MNCC in state 4 (CALL_DELIVERED)
305DCC starting timer T313 with 30 seconds
306DCC (ti 08 sub MSISDN:42342) new state CALL_DELIVERED -> CONNECT_IND
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]307DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
308- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_CONNECT: 8307
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]309- DTAP matches expected message
310- Total time passed: 2.000046 s
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]311 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_CONNECT_ACK
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]312DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]313DRLL Dispatching 04.08 message GSM48_MT_CC_CONNECT_ACK (0x3:0xf)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]314DCC stopping pending timer T313
315DCC (ti 08 sub MSISDN:42342) new state CONNECT_IND -> ACTIVE
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]316DCC (sub 42342) stopping pending guard timer
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]317DMNCC transmit message MNCC_SETUP_COMPL_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]318DCC Sending 'MNCC_SETUP_COMPL_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]319 MSC --> MNCC: callref 0x80000001: MNCC_SETUP_COMPL_IND
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]320DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]321DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]322---
323- RTP stream goes ahead, not shown here.
324- Total time passed: 125.000091 s
325---
326- Call ends
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]327 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_DISCONNECT
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]328DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]329DRLL Dispatching 04.08 message GSM48_MT_CC_DISCONNECT (0x3:0x25)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]330DCC (ti 08 sub MSISDN:42342) new state ACTIVE -> DISCONNECT_IND
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]331DMNCC transmit message MNCC_DISC_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]332DCC Sending 'MNCC_DISC_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]333 MSC --> MNCC: callref 0x80000001: MNCC_DISC_IND
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]334DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]335DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]336DMNCC receive message MNCC_REL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]337DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]338DCC (ti 08 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 12 (DISCONNECT_IND)
339DCC starting timer T308 with 10 seconds
340DCC (ti 08 sub MSISDN:42342) new state DISCONNECT_IND -> RELEASE_REQ
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]341DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
342- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_RELEASE: 832d
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]343- DTAP matches expected message
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]344 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_RELEASE_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]345DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]346DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]347DCC stopping pending timer T308
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]348DMNCC transmit message MNCC_REL_CNF
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]349DCC Sending 'MNCC_REL_CNF' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]350 MSC --> MNCC: callref 0x80000001: MNCC_REL_CNF
351 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x0
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]352DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]353DCC (sub 42342) stopping pending guard timer
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]354DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]355DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x2: dtap)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]356DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]357DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]358DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_UNUSED
359DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_COMMUNICATING}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]360DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]361DREF VLR subscr MSISDN:42342 usage increases to: 3
362DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]363- Iu Release --UTRAN-Iu--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]364- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]365DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]366DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
367DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
368DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]369DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]370DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent RAN_conn(CM_SERVICE_REQ:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]371DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Freeing instance
372DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]373DRLL MSISDN:42342: Freeing RAN connection
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]374DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]375DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASED}: Freeing instance
376DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASED}: Deallocated
377 llist_count(&net->ran_conns) == 0
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]378DREF freeing VLR subscr MSISDN:42342
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]379===== test_call_mo: SUCCESS
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]380
381full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]382talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]383
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]384===== test_call_mt
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]385- Total time passed: 0.000000 s
386- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]387 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]388 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]389DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]390DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]391DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]392DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyr46c06e22019-01-04 17:42:05 +0100[diff] [blame^]393DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: LOCATION UPDATING REQUEST: MI=IMSI-901700000010650 LU-type=NORMAL
394DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: LU/new-LAC: 23/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]395DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]396DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: is child of RAN_conn(LU:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]397DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
398DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]399DREF VLR subscr unknown usage increases to: 1
400DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
401DVLR New subscr, IMSI: 901700000010650
402DREF VLR subscr IMSI:901700000010650 usage increases to: 2
403DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]404DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
405DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
406DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
407DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650)
408DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]409DVLR GSUP tx: 08010809710000000156f0
410GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]411DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]412DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
413DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]414DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]415DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
416DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]417 lu_result_sent == 0
418- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
419<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
420DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
421DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]422DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]423DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]424DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
425DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]426- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
427- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
428- ...autn=8704f5ba55f30000d2ee44b22c8ea919
429- ...expecting res=e229c19e791f2e41
430DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
431<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
432 auth_request_sent == 1
433 lu_result_sent == 0
434- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]435 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]436DREF IMSI:901700000010650: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]437DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100[diff] [blame]438DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]439DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100[diff] [blame]440DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]441DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]442DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]443DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
444DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
445DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650)
446DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
447DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
448DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
449DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
450DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100[diff] [blame]451DMM -> SECURITY MODE CONTROL IMSI:901700000010650
452- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
453- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]454DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]455DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]456DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
457DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100[diff] [blame]458 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]459 lu_result_sent == 0
460- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
461DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]462DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
463DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]464DIUCS IMSI:901700000010650: tx CommonID 901700000010650
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]465- Iu Common ID --UTRAN-Iu--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]466DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
467DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
468DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
469DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
470DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +0200[diff] [blame]471DVLR GSUP tx: 04010809710000000156f0280102
472GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]473DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]474 gsup_tx_confirmed == 1
475 lu_result_sent == 0
476- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
477<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
478DVLR GSUP rx 17: 10010809710000000156f00804032443f2
479DREF VLR subscr IMSI:901700000010650 usage increases to: 2
480DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]481DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]482DVLR GSUP tx: 12010809710000000156f0
483GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
484DREF VLR subscr MSISDN:42342 usage decreases to: 1
485<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
486 lu_result_sent == 0
487- HLR also sends GSUP _UPDATE_LOCATION_RESULT
488<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
489DVLR GSUP rx 11: 06010809710000000156f0
490DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]491DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
492DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
493DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
494DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
495DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
496DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
497DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
498DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
499DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
500DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
501DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
502DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
503DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]504DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
505DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
506DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]507- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
508DREF VLR subscr MSISDN:42342 usage decreases to: 1
509<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
510 lu_result_sent == 1
511- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]512 llist_count(&net->ran_conns) == 1
513ran_conn_is_accepted() == false
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]514- MS sends TMSI Realloc Complete
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]515 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]516DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]517DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
518DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]519DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
520DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]521DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]522DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
523DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
524DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
525DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
526DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
527DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
528DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]529DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
530DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
531DMM RAN_conn(LU:901700000010650){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_UNUSED
532DMM RAN_conn(LU:901700000010650){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]533DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]534DREF VLR subscr MSISDN:42342 usage increases to: 3
535DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]536- Iu Release --UTRAN-Iu--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]537DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]538 iu_release_sent == 1
539- LU was successful, and the conn has already been closed
540- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]541DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]542DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
543DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
544DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]545DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]546DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent RAN_conn(LU:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]547DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
548DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Freeing instance
549DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]550DRLL MSISDN:42342: Freeing RAN connection
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]551DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]552DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Freeing instance
553DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Deallocated
554 llist_count(&net->ran_conns) == 0
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]555DREF VLR subscr MSISDN:42342 usage increases to: 2
556 vsub != NULL == 1
557 strcmp(vsub->imsi, IMSI) == 0
Max33b6d0c2018-12-17 17:15:13 +0100[diff] [blame]558 LAC == 23
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]559DREF VLR subscr MSISDN:42342 usage decreases to: 1
560---
561- after a while, MNCC asks us to setup a call, causing Paging
562DMNCC receive message MNCC_SETUP_REQ
563DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]564DCC (ti ff sub MSISDN:42342 callref 423) New transaction
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]565DREF VLR subscr MSISDN:42342 usage increases to: 3
566DMM Subscriber MSISDN:42342 not paged yet, start paging.
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]567 UTRAN-Iu sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]568 strcmp(paging_expecting_imsi, imsi) == 0
569DREF VLR subscr MSISDN:42342 usage increases to: 4
570DREF VLR subscr MSISDN:42342 usage decreases to: 3
571 paging_sent == 1
572 paging_stopped == 0
573- MS replies with Paging Response, and VLR sends Auth Request
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]574 MSC <--UTRAN-Iu-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]575 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]576DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]577DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]578DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]579DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyr46c06e22019-01-04 17:42:05 +0100[diff] [blame^]580DRR RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_NEW}: PAGING RESPONSE: MI(IMSI)=901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]581DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]582DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: is child of RAN_conn(PAGING_RESP:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]583DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
584DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]585DREF VLR subscr MSISDN:42342 usage increases to: 4
586DREF VLR subscr MSISDN:42342 usage increases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]587DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
588DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
589DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
590DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(PAGING_RESP:901700000010650)
591DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
592DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
593DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]594- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
595- ...rand=c187a53a5e6b9d573cac7c74451fd46d
596- ...autn=1843a645b98d00005b2d666af46c45d9
597- ...expecting res=7db47cf7f81e4dc7
598DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]599DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
600DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]601DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]602DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
603DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]604 auth_request_sent == 1
605- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]606 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]607DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]608DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100[diff] [blame]609DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]610DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100[diff] [blame]611DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]612DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]613DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]614DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
615DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
616DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(PAGING_RESP:901700000010650)
617DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
618DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
619DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]620DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
621DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100[diff] [blame]622DMM -> SECURITY MODE CONTROL MSISDN:42342
623- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
624- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]625DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]626DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]627DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
628DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100[diff] [blame]629 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]630- MS sends SecurityModeControl acceptance, VLR accepts, sends CC Setup
631DMM <- SECURITY MODE COMPLETE MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]632DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
633DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]634DIUCS MSISDN:42342: tx CommonID 901700000010650
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]635- Iu Common ID --UTRAN-Iu--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]636DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
637DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
638DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
639DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]640DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]641DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]642DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]643DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]644DPAG Paging success for MSISDN:42342 (event=0)
645DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]646DCC Paging subscr 42342 succeeded!
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]647DREF MSISDN:42342: MSC conn use + trans_cc == 1 (0x10: trans_cc)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]648DCC starting timer T303 with 30 seconds
649DCC (ti 00 sub MSISDN:42342) new state NULL -> CALL_PRESENT
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]650DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
651- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_SETUP: 0305
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]652- DTAP matches expected message
653DREF VLR subscr MSISDN:42342 usage decreases to: 3
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]654DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
655DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_ACCEPTED}: ran_conn_fsm_has_active_transactions: connection still has active transaction: CC
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]656 paging_stopped == 1
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]657 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_CALL_CONF
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]658DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]659DRLL Dispatching 04.08 message GSM48_MT_CC_CALL_CONF (0x3:0x8)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]660DCC stopping pending timer T303
661DCC starting timer T310 with 30 seconds
662DCC (ti 00 sub MSISDN:42342) new state CALL_PRESENT -> MO_TERM_CALL_CONF
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]663 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x423
664DMNCC transmit message MNCC_CALL_CONF_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]665DCC Sending 'MNCC_CALL_CONF_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]666 MSC --> MNCC: callref 0x423: MNCC_CALL_CONF_IND
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]667DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMMUNICATING
668DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]669DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]670- Total time passed: 1.000023 s
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]671 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_ALERTING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]672DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]673DRLL Dispatching 04.08 message GSM48_MT_CC_ALERTING (0x3:0x1)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]674DCC stopping pending timer T310
675DCC starting timer T301 with 180 seconds
676DCC (ti 00 sub MSISDN:42342) new state MO_TERM_CALL_CONF -> CALL_RECEIVED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]677DMNCC transmit message MNCC_ALERT_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]678DCC Sending 'MNCC_ALERT_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]679 MSC --> MNCC: callref 0x423: MNCC_ALERT_IND
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]680DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]681DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]682- Total time passed: 2.000046 s
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]683 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_CONNECT
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]684DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]685DRLL Dispatching 04.08 message GSM48_MT_CC_CONNECT (0x3:0x7)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]686DCC stopping pending timer T301
687DCC (ti 00 sub MSISDN:42342) new state CALL_RECEIVED -> CONNECT_REQUEST
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]688DMNCC transmit message MNCC_SETUP_CNF
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]689DCC Sending 'MNCC_SETUP_CNF' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]690 MSC --> MNCC: callref 0x423: MNCC_SETUP_CNF
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]691DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]692DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]693DMNCC receive message MNCC_SETUP_COMPL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]694DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]695DCC (ti 00 sub 42342) Received 'MNCC_SETUP_COMPL_REQ' from MNCC in state 8 (CONNECT_REQUEST)
696DCC (ti 00 sub MSISDN:42342) new state CONNECT_REQUEST -> ACTIVE
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]697DCC (sub 42342) stopping pending guard timer
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]698DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
699- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_CONNECT_ACK: 030f
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]700- DTAP matches expected message
701---
702- RTP stream goes ahead, not shown here.
703- Total time passed: 125.000091 s
704---
705- Call ends
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]706 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_DISCONNECT
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]707DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]708DRLL Dispatching 04.08 message GSM48_MT_CC_DISCONNECT (0x3:0x25)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]709DCC (ti 00 sub MSISDN:42342) new state ACTIVE -> DISCONNECT_IND
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]710DMNCC transmit message MNCC_DISC_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]711DCC Sending 'MNCC_DISC_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]712 MSC --> MNCC: callref 0x423: MNCC_DISC_IND
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]713DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]714DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]715DMNCC receive message MNCC_REL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]716DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]717DCC (ti 00 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 12 (DISCONNECT_IND)
718DCC starting timer T308 with 10 seconds
719DCC (ti 00 sub MSISDN:42342) new state DISCONNECT_IND -> RELEASE_REQ
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]720DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
721- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_RELEASE: 032d
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]722- DTAP matches expected message
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]723 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_RELEASE_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]724DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]725DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]726DCC stopping pending timer T308
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]727DMNCC transmit message MNCC_REL_CNF
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]728DCC Sending 'MNCC_REL_CNF' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]729 MSC --> MNCC: callref 0x423: MNCC_REL_CNF
730 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x0
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]731DCC (ti 00 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]732DCC (sub 42342) stopping pending guard timer
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]733DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]734DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x2: dtap)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]735DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]736DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]737DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_UNUSED
738DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_COMMUNICATING}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]739DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]740DREF VLR subscr MSISDN:42342 usage increases to: 3
741DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]742- Iu Release --UTRAN-Iu--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]743- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]744DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]745DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
746DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
747DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]748DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]749DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Removing from parent RAN_conn(PAGING_RESP:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]750DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Freeing instance
751DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]752DRLL MSISDN:42342: Freeing RAN connection
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]753DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]754DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_RELEASED}: Freeing instance
755DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_RELEASED}: Deallocated
756 llist_count(&net->ran_conns) == 0
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]757DREF freeing VLR subscr MSISDN:42342
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]758===== test_call_mt: SUCCESS
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]759
760full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]761talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]762
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]763===== test_call_mt2
764- Total time passed: 0.000000 s
765- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]766 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]767 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]768DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]769DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]770DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]771DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyr46c06e22019-01-04 17:42:05 +0100[diff] [blame^]772DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: LOCATION UPDATING REQUEST: MI=IMSI-901700000010650 LU-type=NORMAL
773DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: LU/new-LAC: 23/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]774DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]775DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: is child of RAN_conn(LU:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]776DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
777DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]778DREF VLR subscr unknown usage increases to: 1
779DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
780DVLR New subscr, IMSI: 901700000010650
781DREF VLR subscr IMSI:901700000010650 usage increases to: 2
782DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]783DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
784DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
785DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
786DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650)
787DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]788DVLR GSUP tx: 08010809710000000156f0
789GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]790DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]791DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
792DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]793DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]794DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
795DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]796 lu_result_sent == 0
797- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
798<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
799DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
800DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]801DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]802DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]803DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
804DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]805- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
806- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
807- ...autn=8704f5ba55f30000d2ee44b22c8ea919
808- ...expecting res=e229c19e791f2e41
809DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
810<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
811 auth_request_sent == 1
812 lu_result_sent == 0
813- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]814 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]815DREF IMSI:901700000010650: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]816DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
817DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]818DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]819DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
820DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]821DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]822DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
823DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
824DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650)
825DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
826DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
827DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
828DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
829DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]830DMM -> SECURITY MODE CONTROL IMSI:901700000010650
831- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
832- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]833DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]834DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]835DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
836DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]837 security_mode_ctrl_sent == 1
838 lu_result_sent == 0
839- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
840DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]841DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
842DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]843DIUCS IMSI:901700000010650: tx CommonID 901700000010650
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]844- Iu Common ID --UTRAN-Iu--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]845DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
846DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
847DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
848DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
849DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +0200[diff] [blame]850DVLR GSUP tx: 04010809710000000156f0280102
851GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]852DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]853 gsup_tx_confirmed == 1
854 lu_result_sent == 0
855- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
856<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
857DVLR GSUP rx 17: 10010809710000000156f00804032443f2
858DREF VLR subscr IMSI:901700000010650 usage increases to: 2
859DVLR IMSI:901700000010650 has MSISDN:42342
860DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
861DVLR GSUP tx: 12010809710000000156f0
862GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
863DREF VLR subscr MSISDN:42342 usage decreases to: 1
864<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
865 lu_result_sent == 0
866- HLR also sends GSUP _UPDATE_LOCATION_RESULT
867<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
868DVLR GSUP rx 11: 06010809710000000156f0
869DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]870DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
871DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
872DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
873DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
874DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
875DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
876DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
877DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
878DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
879DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
880DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
881DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
882DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]883DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
884DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
885DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]886- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
887DREF VLR subscr MSISDN:42342 usage decreases to: 1
888<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
889 lu_result_sent == 1
890- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]891 llist_count(&net->ran_conns) == 1
892ran_conn_is_accepted() == false
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]893- MS sends TMSI Realloc Complete
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]894 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]895DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]896DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
897DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]898DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
899DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]900DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]901DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
902DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
903DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
904DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
905DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
906DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
907DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]908DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
909DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
910DMM RAN_conn(LU:901700000010650){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_UNUSED
911DMM RAN_conn(LU:901700000010650){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]912DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]913DREF VLR subscr MSISDN:42342 usage increases to: 3
914DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]915- Iu Release --UTRAN-Iu--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]916DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]917 iu_release_sent == 1
918- LU was successful, and the conn has already been closed
919- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]920DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]921DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
922DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
923DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]924DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]925DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent RAN_conn(LU:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]926DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
927DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Freeing instance
928DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]929DRLL MSISDN:42342: Freeing RAN connection
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]930DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]931DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Freeing instance
932DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Deallocated
933 llist_count(&net->ran_conns) == 0
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]934DREF VLR subscr MSISDN:42342 usage increases to: 2
935 vsub != NULL == 1
936 strcmp(vsub->imsi, IMSI) == 0
Max33b6d0c2018-12-17 17:15:13 +0100[diff] [blame]937 LAC == 23
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]938DREF VLR subscr MSISDN:42342 usage decreases to: 1
939---
940- after a while, MNCC asks us to setup a call, causing Paging
941DMNCC receive message MNCC_SETUP_REQ
942DREF VLR subscr MSISDN:42342 usage increases to: 2
943DCC (ti ff sub MSISDN:42342 callref 423) New transaction
944DREF VLR subscr MSISDN:42342 usage increases to: 3
945DMM Subscriber MSISDN:42342 not paged yet, start paging.
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]946 UTRAN-Iu sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]947 strcmp(paging_expecting_imsi, imsi) == 0
948DREF VLR subscr MSISDN:42342 usage increases to: 4
949DREF VLR subscr MSISDN:42342 usage decreases to: 3
950 paging_sent == 1
951 paging_stopped == 0
952- MS replies with Paging Response, and VLR sends Auth Request
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]953 MSC <--UTRAN-Iu-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]954 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]955DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]956DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]957DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]958DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyr46c06e22019-01-04 17:42:05 +0100[diff] [blame^]959DRR RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_NEW}: PAGING RESPONSE: MI(IMSI)=901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]960DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]961DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: is child of RAN_conn(PAGING_RESP:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]962DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
963DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]964DREF VLR subscr MSISDN:42342 usage increases to: 4
965DREF VLR subscr MSISDN:42342 usage increases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]966DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
967DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
968DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
969DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(PAGING_RESP:901700000010650)
970DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
971DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
972DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]973- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
974- ...rand=c187a53a5e6b9d573cac7c74451fd46d
975- ...autn=1843a645b98d00005b2d666af46c45d9
976- ...expecting res=7db47cf7f81e4dc7
977DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]978DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
979DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]980DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]981DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
982DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]983 auth_request_sent == 1
984- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]985 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]986DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]987DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
988DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]989DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]990DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
991DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]992DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]993DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
994DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
995DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(PAGING_RESP:901700000010650)
996DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
997DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
998DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]999DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1000DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1001DMM -> SECURITY MODE CONTROL MSISDN:42342
1002- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1003- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1004DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1005DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1006DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
1007DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1008 security_mode_ctrl_sent == 1
1009- MS sends SecurityModeControl acceptance, VLR accepts, sends CC Setup
1010DMM <- SECURITY MODE COMPLETE MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1011DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
1012DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1013DIUCS MSISDN:42342: tx CommonID 901700000010650
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1014- Iu Common ID --UTRAN-Iu--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1015DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
1016DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
1017DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
1018DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1019DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1020DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1021DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1022DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1023DPAG Paging success for MSISDN:42342 (event=0)
1024DPAG Calling paging cbfn.
1025DCC Paging subscr 42342 succeeded!
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1026DREF MSISDN:42342: MSC conn use + trans_cc == 1 (0x10: trans_cc)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1027DCC starting timer T303 with 30 seconds
1028DCC (ti 00 sub MSISDN:42342) new state NULL -> CALL_PRESENT
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1029DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
1030- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_SETUP: 0305
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1031- DTAP matches expected message
1032DREF VLR subscr MSISDN:42342 usage decreases to: 3
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1033DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
1034DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_ACCEPTED}: ran_conn_fsm_has_active_transactions: connection still has active transaction: CC
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1035 paging_stopped == 1
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1036 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_CALL_CONF
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1037DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1038DRLL Dispatching 04.08 message GSM48_MT_CC_CALL_CONF (0x3:0x8)
1039DCC stopping pending timer T303
1040DCC starting timer T310 with 30 seconds
1041DCC (ti 00 sub MSISDN:42342) new state CALL_PRESENT -> MO_TERM_CALL_CONF
1042 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x423
1043DMNCC transmit message MNCC_CALL_CONF_IND
1044DCC Sending 'MNCC_CALL_CONF_IND' to MNCC.
1045 MSC --> MNCC: callref 0x423: MNCC_CALL_CONF_IND
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1046DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMMUNICATING
1047DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1048DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1049- Total time passed: 1.000023 s
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1050 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_ALERTING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1051DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1052DRLL Dispatching 04.08 message GSM48_MT_CC_ALERTING (0x3:0x1)
1053DCC stopping pending timer T310
1054DCC starting timer T301 with 180 seconds
1055DCC (ti 00 sub MSISDN:42342) new state MO_TERM_CALL_CONF -> CALL_RECEIVED
1056DMNCC transmit message MNCC_ALERT_IND
1057DCC Sending 'MNCC_ALERT_IND' to MNCC.
1058 MSC --> MNCC: callref 0x423: MNCC_ALERT_IND
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1059DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1060DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1061- Total time passed: 16.000046 s
1062- The call failed, the BSC sends a BSSMAP Clear Request
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1063DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_CN_CLOSE
1064DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_COMMUNICATING}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1065DREF MSISDN:42342: MSC conn use + release == 2 (0x110: trans_cc,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1066DREF VLR subscr MSISDN:42342 usage increases to: 4
1067DREF VLR subscr MSISDN:42342 usage decreases to: 3
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1068DCC stopping pending timer T301
1069 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x423
1070DMNCC receive message MNCC_REL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]1071DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1072DCC (ti 00 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 7 (CALL_RECEIVED)
1073DCC starting timer T308 with 10 seconds
1074DCC (ti 00 sub MSISDN:42342) new state CALL_RECEIVED -> RELEASE_REQ
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1075DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
1076- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_RELEASE: 032d
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1077- DTAP matches expected message
1078DMNCC transmit message MNCC_REL_CNF
1079DCC Sending 'MNCC_REL_CNF' to MNCC.
1080 MSC --> MNCC: callref 0x423: MNCC_REL_CNF
Neels Hofmeyrdc2514b2018-04-09 23:29:14 +0200[diff] [blame]1081DCC stopping pending timer T308
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1082DCC (ti 00 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]1083DCC (sub 42342) stopping pending guard timer
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1084DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1085DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x100: release)
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1086- Iu Release --UTRAN-Iu--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1087- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1088DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1089DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
1090DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
1091DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1092DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1093DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Removing from parent RAN_conn(PAGING_RESP:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1094DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Freeing instance
1095DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1096DRLL MSISDN:42342: Freeing RAN connection
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1097DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1098DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_RELEASED}: Freeing instance
1099DMM RAN_conn(PAGING_RESP:901700000010650){RAN_CONN_S_RELEASED}: Deallocated
1100 llist_count(&net->ran_conns) == 0
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1101- Total time passed: 31.000069 s
1102DREF freeing VLR subscr MSISDN:42342
1103===== test_call_mt2: SUCCESS
1104
1105full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]1106talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100[diff] [blame]1107
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1108===== test_call_mo_to_unknown
1109- Total time passed: 0.000000 s
1110- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1111 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1112 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1113DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1114DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1115DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1116DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyr46c06e22019-01-04 17:42:05 +0100[diff] [blame^]1117DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: LOCATION UPDATING REQUEST: MI=IMSI-901700000010650 LU-type=NORMAL
1118DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: LU/new-LAC: 23/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1119DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1120DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: is child of RAN_conn(LU:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1121DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
1122DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1123DREF VLR subscr unknown usage increases to: 1
1124DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1125DVLR New subscr, IMSI: 901700000010650
1126DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1127DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1128DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1129DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1130DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1131DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650)
1132DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1133DVLR GSUP tx: 08010809710000000156f0
1134GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1135DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1136DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
1137DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1138DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1139DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
1140DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1141 lu_result_sent == 0
1142- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1143<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1144DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1145DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1146DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1147DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1148DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
1149DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1150- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1151- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1152- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1153- ...expecting res=e229c19e791f2e41
1154DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1155<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1156 auth_request_sent == 1
1157 lu_result_sent == 0
1158- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1159 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1160DREF IMSI:901700000010650: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1161DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1162DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1163DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1164DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
1165DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1166DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1167DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1168DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1169DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1170DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1171DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1172DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1173DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1174DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1175DMM -> SECURITY MODE CONTROL IMSI:901700000010650
1176- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1177- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1178DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1179DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1180DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
1181DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1182 security_mode_ctrl_sent == 1
1183 lu_result_sent == 0
1184- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
1185DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1186DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1187DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1188DIUCS IMSI:901700000010650: tx CommonID 901700000010650
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1189- Iu Common ID --UTRAN-Iu--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1190DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1191DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1192DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1193DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
1194DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +0200[diff] [blame]1195DVLR GSUP tx: 04010809710000000156f0280102
1196GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1197DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1198 gsup_tx_confirmed == 1
1199 lu_result_sent == 0
1200- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1201<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1202DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1203DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1204DVLR IMSI:901700000010650 has MSISDN:42342
1205DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
1206DVLR GSUP tx: 12010809710000000156f0
1207GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1208DREF VLR subscr MSISDN:42342 usage decreases to: 1
1209<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1210 lu_result_sent == 0
1211- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1212<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1213DVLR GSUP rx 11: 06010809710000000156f0
1214DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1215DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1216DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1217DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1218DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1219DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1220DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1221DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1222DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1223DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1224DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1225DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
1226DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1227DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1228DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1229DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1230DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1231- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
1232DREF VLR subscr MSISDN:42342 usage decreases to: 1
1233<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1234 lu_result_sent == 1
1235- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1236 llist_count(&net->ran_conns) == 1
1237ran_conn_is_accepted() == false
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1238- MS sends TMSI Realloc Complete
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1239 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1240DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1241DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
1242DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1243DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1244DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1245DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1246DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1247DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1248DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1249DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1250DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1251DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1252DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1253DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
1254DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
1255DMM RAN_conn(LU:901700000010650){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_UNUSED
1256DMM RAN_conn(LU:901700000010650){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1257DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1258DREF VLR subscr MSISDN:42342 usage increases to: 3
1259DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1260- Iu Release --UTRAN-Iu--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1261DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1262 iu_release_sent == 1
1263- LU was successful, and the conn has already been closed
1264- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1265DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1266DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
1267DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
1268DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1269DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1270DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent RAN_conn(LU:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1271DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1272DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Freeing instance
1273DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1274DRLL MSISDN:42342: Freeing RAN connection
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1275DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1276DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Freeing instance
1277DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Deallocated
1278 llist_count(&net->ran_conns) == 0
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1279DREF VLR subscr MSISDN:42342 usage increases to: 2
1280 vsub != NULL == 1
1281 strcmp(vsub->imsi, IMSI) == 0
Max33b6d0c2018-12-17 17:15:13 +0100[diff] [blame]1282 LAC == 23
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1283DREF VLR subscr MSISDN:42342 usage decreases to: 1
1284---
1285- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1286 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1287 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1288DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1289DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1290DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr46c06e22019-01-04 17:42:05 +0100[diff] [blame^]1291DMM RAN_conn{RAN_CONN_S_NEW}: Rx CM SERVICE REQUEST cm_service_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1292DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1293DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1294DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: is child of RAN_conn(CM_SERVICE_REQ:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1295DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
1296DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1297DREF VLR subscr MSISDN:42342 usage increases to: 2
1298DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1299DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1300DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1301DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1302DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
1303DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1304DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
1305DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1306- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
1307- ...rand=c187a53a5e6b9d573cac7c74451fd46d
1308- ...autn=1843a645b98d00005b2d666af46c45d9
1309- ...expecting res=7db47cf7f81e4dc7
1310DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1311DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
1312DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1313DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1314DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
1315DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1316 cm_service_result_sent == 0
1317 auth_request_sent == 1
1318- needs auth, not yet accepted
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1319ran_conn_is_accepted() == false
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1320- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1321 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1322DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1323DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1324DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1325DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1326DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
1327DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1328DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1329DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1330DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1331DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
1332DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1333DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1334DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1335DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1336DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1337DMM -> SECURITY MODE CONTROL MSISDN:42342
1338- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1339- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1340DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1341DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1342DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
1343DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1344 security_mode_ctrl_sent == 1
1345 cm_service_result_sent == 0
1346- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
1347DMM <- SECURITY MODE COMPLETE MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1348DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
1349DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1350DIUCS MSISDN:42342: tx CommonID 901700000010650
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1351- Iu Common ID --UTRAN-Iu--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1352DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
1353DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
1354DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
1355DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1356DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1357DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1358DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1359DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1360DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1361DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
1362DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_ACCEPTED}: ran_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1363 cm_service_result_sent == 0
1364---
1365- a call is initiated
1366- SETUP gets forwarded to MNCC
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1367 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_SETUP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1368DREF MSISDN:42342: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1369DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1370DCC Unknown transaction ID 8, creating new trans.
1371DCC (ti 08 sub MSISDN:42342 callref 80000002) New transaction
1372DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1373DREF MSISDN:42342: MSC conn use + trans_cc == 3 (0x1a: dtap,cm_service,trans_cc)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1374DMM MSISDN:42342: rx msg GSM48_MT_CC_SETUP: received_cm_service_request changes to false
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1375DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x12: dtap,trans_cc)
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]1376DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1377DCC (ti 08 sub MSISDN:42342) new state NULL -> INITIATED
1378DCC Subscriber MSISDN:42342 (42342) sends SETUP to 123
1379DMNCC transmit message MNCC_SETUP_IND
1380DCC Sending 'MNCC_SETUP_IND' to MNCC.
1381 MSC --> MNCC: callref 0x80000002: MNCC_SETUP_IND
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1382DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMMUNICATING
1383DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1384DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1385- MNCC says that's fine
1386DMNCC receive message MNCC_CALL_PROC_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]1387DCC (sub 42342) stopping pending guard timer
1388DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1389DCC (ti 08 sub 42342) Received 'MNCC_CALL_PROC_REQ' from MNCC in state 1 (INITIATED)
1390DCC (ti 08 sub MSISDN:42342) new state INITIATED -> MO_CALL_PROC
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1391DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
1392- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_CALL_PROC: 8302
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1393- DTAP matches expected message
1394 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x80000002
1395- But the other side's MSISDN could not be resolved, MNCC tells us to cancel
1396DMNCC receive message MNCC_REL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]1397DCC (sub 42342) stopping pending guard timer
1398DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1399DCC (ti 08 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 3 (MO_CALL_PROC)
1400DCC starting timer T308 with 10 seconds
1401DCC (ti 08 sub MSISDN:42342) new state MO_CALL_PROC -> RELEASE_REQ
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1402DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
1403- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_RELEASE: 832d
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1404- DTAP matches expected message
1405- Total time passed: 10.000023 s
1406DCC starting timer T308 with 10 seconds
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1407DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
1408- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_RELEASE: 832d
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1409- DTAP matches expected message
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1410 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_RELEASE_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1411DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1412DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a)
1413DCC stopping pending timer T308
1414DMNCC transmit message MNCC_REL_CNF
1415DCC Sending 'MNCC_REL_CNF' to MNCC.
1416 MSC --> MNCC: callref 0x80000002: MNCC_REL_CNF
1417 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x0
1418DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]1419DCC (sub 42342) stopping pending guard timer
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1420DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1421DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x2: dtap)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1422DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1423DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1424DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_UNUSED
1425DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_COMMUNICATING}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1426DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1427DREF VLR subscr MSISDN:42342 usage increases to: 3
1428DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1429- Iu Release --UTRAN-Iu--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1430- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1431DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1432DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
1433DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
1434DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1435DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1436DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent RAN_conn(CM_SERVICE_REQ:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1437DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Freeing instance
1438DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1439DRLL MSISDN:42342: Freeing RAN connection
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1440DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1441DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASED}: Freeing instance
1442DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASED}: Deallocated
1443 llist_count(&net->ran_conns) == 0
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1444DREF freeing VLR subscr MSISDN:42342
1445===== test_call_mo_to_unknown: SUCCESS
1446
1447full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]1448talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1449
1450===== test_call_mo_to_unknown_timeout
1451- Total time passed: 0.000000 s
1452- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1453 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1454 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1455DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1456DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1457DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1458DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyr46c06e22019-01-04 17:42:05 +0100[diff] [blame^]1459DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: LOCATION UPDATING REQUEST: MI=IMSI-901700000010650 LU-type=NORMAL
1460DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: LU/new-LAC: 23/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1461DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1462DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: is child of RAN_conn(LU:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1463DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
1464DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1465DREF VLR subscr unknown usage increases to: 1
1466DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1467DVLR New subscr, IMSI: 901700000010650
1468DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1469DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1470DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1471DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1472DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1473DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650)
1474DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1475DVLR GSUP tx: 08010809710000000156f0
1476GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1477DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1478DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
1479DMM RAN_conn(LU:901700000010650){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1480DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1481DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
1482DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1483 lu_result_sent == 0
1484- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1485<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1486DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1487DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1488DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1489DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1490DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
1491DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1492- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1493- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1494- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1495- ...expecting res=e229c19e791f2e41
1496DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1497<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1498 auth_request_sent == 1
1499 lu_result_sent == 0
1500- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1501 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1502DREF IMSI:901700000010650: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1503DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1504DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1505DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1506DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
1507DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1508DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1509DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1510DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1511DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1512DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1513DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1514DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1515DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1516DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1517DMM -> SECURITY MODE CONTROL IMSI:901700000010650
1518- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1519- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1520DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1521DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1522DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
1523DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1524 security_mode_ctrl_sent == 1
1525 lu_result_sent == 0
1526- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
1527DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1528DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1529DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1530DIUCS IMSI:901700000010650: tx CommonID 901700000010650
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1531- Iu Common ID --UTRAN-Iu--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1532DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1533DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1534DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1535DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
1536DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +0200[diff] [blame]1537DVLR GSUP tx: 04010809710000000156f0280102
1538GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1539DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1540 gsup_tx_confirmed == 1
1541 lu_result_sent == 0
1542- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1543<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1544DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1545DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1546DVLR IMSI:901700000010650 has MSISDN:42342
1547DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
1548DVLR GSUP tx: 12010809710000000156f0
1549GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1550DREF VLR subscr MSISDN:42342 usage decreases to: 1
1551<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1552 lu_result_sent == 0
1553- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1554<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1555DVLR GSUP rx 11: 06010809710000000156f0
1556DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1557DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1558DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1559DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1560DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1561DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1562DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1563DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1564DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1565DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1566DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1567DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
1568DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1569DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1570DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1571DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1572DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1573- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
1574DREF VLR subscr MSISDN:42342 usage decreases to: 1
1575<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1576 lu_result_sent == 1
1577- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1578 llist_count(&net->ran_conns) == 1
1579ran_conn_is_accepted() == false
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1580- MS sends TMSI Realloc Complete
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1581 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1582DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1583DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
1584DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1585DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1586DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1587DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1588DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1589DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1590DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1591DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1592DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1593DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1594DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1595DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
1596DMM RAN_conn(LU:901700000010650){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
1597DMM RAN_conn(LU:901700000010650){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_UNUSED
1598DMM RAN_conn(LU:901700000010650){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1599DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1600DREF VLR subscr MSISDN:42342 usage increases to: 3
1601DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1602- Iu Release --UTRAN-Iu--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1603DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1604 iu_release_sent == 1
1605- LU was successful, and the conn has already been closed
1606- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1607DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1608DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
1609DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
1610DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1611DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1612DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent RAN_conn(LU:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1613DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1614DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Freeing instance
1615DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1616DRLL MSISDN:42342: Freeing RAN connection
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1617DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1618DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Freeing instance
1619DMM RAN_conn(LU:901700000010650){RAN_CONN_S_RELEASED}: Deallocated
1620 llist_count(&net->ran_conns) == 0
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1621DREF VLR subscr MSISDN:42342 usage increases to: 2
1622 vsub != NULL == 1
1623 strcmp(vsub->imsi, IMSI) == 0
Max33b6d0c2018-12-17 17:15:13 +0100[diff] [blame]1624 LAC == 23
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1625DREF VLR subscr MSISDN:42342 usage decreases to: 1
1626---
1627- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1628 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1629 new conn
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1630DMM RAN_conn{RAN_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1631DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1632DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr46c06e22019-01-04 17:42:05 +0100[diff] [blame^]1633DMM RAN_conn{RAN_CONN_S_NEW}: Rx CM SERVICE REQUEST cm_service_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1634DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_NEW}: Updated ID
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1635DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Allocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1636DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: is child of RAN_conn(CM_SERVICE_REQ:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1637DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
1638DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1639DREF VLR subscr MSISDN:42342 usage increases to: 2
1640DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1641DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1642DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1643DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1644DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
1645DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1646DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
1647DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1648- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
1649- ...rand=c187a53a5e6b9d573cac7c74451fd46d
1650- ...autn=1843a645b98d00005b2d666af46c45d9
1651- ...expecting res=7db47cf7f81e4dc7
1652DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1653DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_NEW}: Received Event RAN_CONN_E_COMPLETE_LAYER_3
1654DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_NEW}: state_chg to RAN_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1655DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1656DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
1657DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1658 cm_service_result_sent == 0
1659 auth_request_sent == 1
1660- needs auth, not yet accepted
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1661ran_conn_is_accepted() == false
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1662- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1663 MSC <--UTRAN-Iu-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1664DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1665DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1666DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1667DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1668DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
1669DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1670DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1671DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1672DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1673DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
1674DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1675DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1676DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1677DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1678DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1679DMM -> SECURITY MODE CONTROL MSISDN:42342
1680- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1681- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1682DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1683DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1684DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_UNUSED
1685DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event RAN_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1686 security_mode_ctrl_sent == 1
1687 cm_service_result_sent == 0
1688- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
1689DMM <- SECURITY MODE COMPLETE MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1690DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
1691DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1692DIUCS MSISDN:42342: tx CommonID 901700000010650
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1693- Iu Common ID --UTRAN-Iu--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1694DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
1695DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
1696DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
1697DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1698DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1699DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200[diff] [blame]1700DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1701DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: Received Event RAN_CONN_E_ACCEPTED
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1702DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1703DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_AUTH_CIPH}: state_chg to RAN_CONN_S_ACCEPTED
1704DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_ACCEPTED}: ran_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1705 cm_service_result_sent == 0
1706---
1707- a call is initiated
1708- SETUP gets forwarded to MNCC
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1709 MSC <--UTRAN-Iu-- MS: GSM48_MT_CC_SETUP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1710DREF MSISDN:42342: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1711DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1712DCC Unknown transaction ID 8, creating new trans.
1713DCC (ti 08 sub MSISDN:42342 callref 80000003) New transaction
1714DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1715DREF MSISDN:42342: MSC conn use + trans_cc == 3 (0x1a: dtap,cm_service,trans_cc)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1716DMM MSISDN:42342: rx msg GSM48_MT_CC_SETUP: received_cm_service_request changes to false
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1717DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x12: dtap,trans_cc)
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]1718DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1719DCC (ti 08 sub MSISDN:42342) new state NULL -> INITIATED
1720DCC Subscriber MSISDN:42342 (42342) sends SETUP to 123
1721DMNCC transmit message MNCC_SETUP_IND
1722DCC Sending 'MNCC_SETUP_IND' to MNCC.
1723 MSC --> MNCC: callref 0x80000003: MNCC_SETUP_IND
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1724DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_ACCEPTED}: Received Event RAN_CONN_E_COMMUNICATING
1725DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_ACCEPTED}: state_chg to RAN_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1726DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1727- MNCC says that's fine
1728DMNCC receive message MNCC_CALL_PROC_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]1729DCC (sub 42342) stopping pending guard timer
1730DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1731DCC (ti 08 sub 42342) Received 'MNCC_CALL_PROC_REQ' from MNCC in state 1 (INITIATED)
1732DCC (ti 08 sub MSISDN:42342) new state INITIATED -> MO_CALL_PROC
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1733DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
1734- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_CALL_PROC: 8302
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1735- DTAP matches expected message
1736 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x80000003
1737- But the other side's MSISDN could not be resolved, MNCC tells us to cancel
1738DMNCC receive message MNCC_REL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]1739DCC (sub 42342) stopping pending guard timer
1740DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1741DCC (ti 08 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 3 (MO_CALL_PROC)
1742DCC starting timer T308 with 10 seconds
1743DCC (ti 08 sub MSISDN:42342) new state MO_CALL_PROC -> RELEASE_REQ
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1744DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
1745- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_RELEASE: 832d
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1746- DTAP matches expected message
1747- Despite our repeated CC Release Requests, the MS does not respond anymore
1748- Total time passed: 10.000023 s
1749DCC starting timer T308 with 10 seconds
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1750DMSC msc_tx 2 bytes to MSISDN:42342 via UTRAN-Iu
1751- DTAP --UTRAN-Iu--> MS: GSM48_MT_CC_RELEASE: 832d
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1752- DTAP matches expected message
1753- The CC Release times out and we still properly clear the conn
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1754- Total time passed: 20.000046 s
1755 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x80000003
1756DMNCC transmit message MNCC_REL_CNF
1757DCC Sending 'MNCC_REL_CNF' to MNCC.
1758 MSC --> MNCC: callref 0x80000003: MNCC_REL_CNF
1759DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Philipp Maier9ca7b312018-10-10 17:00:49 +0200[diff] [blame]1760DCC (sub 42342) stopping pending guard timer
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1761DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1762DREF MSISDN:42342: MSC conn use - trans_cc == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1763DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_COMMUNICATING}: Received Event RAN_CONN_E_UNUSED
1764DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_COMMUNICATING}: state_chg to RAN_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1765DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200[diff] [blame]1766DREF VLR subscr MSISDN:42342 usage increases to: 3
1767DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr7814a832018-12-26 00:40:18 +0100[diff] [blame]1768- Iu Release --UTRAN-Iu--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200[diff] [blame]1769- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200[diff] [blame]1770DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1771DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASING}: Received Event RAN_CONN_E_UNUSED
1772DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASING}: state_chg to RAN_CONN_S_RELEASED
1773DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1774DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1775DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent RAN_conn(CM_SERVICE_REQ:901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200[diff] [blame]1776DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Freeing instance
1777DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1778DRLL MSISDN:42342: Freeing RAN connection
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1779DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrc036b792018-11-29 22:37:51 +0100[diff] [blame]1780DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASED}: Freeing instance
1781DMM RAN_conn(CM_SERVICE_REQ:901700000010650){RAN_CONN_S_RELEASED}: Deallocated
1782 llist_count(&net->ran_conns) == 0
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1783DREF freeing VLR subscr MSISDN:42342
1784===== test_call_mo_to_unknown_timeout: SUCCESS
1785
1786full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]1787talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1788
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]1789full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Stefan Sperlingafa030d2018-12-06 12:06:59 +0100[diff] [blame]1790talloc_total_blocks(tall_bsc_ctx) == 13
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]1791