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