Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / e2f24d53e4f80b34ec6d656d93127cb598229a96 / . / tests / msc_vlr / msc_vlr_test_umts_authen.err
blob: 744004ac5c4b17a5cc79618baaa34b0f71649282 [file] [log] [blame]
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1===== test_umts_authen_geran
2- Location Update request causes a GSUP Send Auth Info request to HLR
3 rx from MS: pdisc=0x05 msg_type=0x08
4 new conn
5DREF unknown: MSC conn use + 1 == 1
6DRLL Dispatching 04.08 message, pdisc=5
7DREF unknown: MSC conn use + 1 == 2
8DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
9DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
10DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
11DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
12DMM LU/new-LAC: 0/0
13DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
14DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
15DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth (no Ciph)
16DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
17DREF VLR subscr unknown usage increases to: 1
18DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
19DVLR New subscr, IMSI: 901700000010650
20DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]21DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]22DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
23DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
24DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
25DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
26DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
27DVLR GSUP tx: 08010809710000000156f0
28GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
29DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]30DMM compl_l3: Keeping conn
31DREF IMSI:901700000010650: MSC conn use - 1 == 1
32 lu_result_sent == 0
33- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
34<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
35DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
36DREF VLR subscr IMSI:901700000010650 usage increases to: 2
37DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
38DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
39DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
40DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
41- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
42- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
43- ...autn=8704f5ba55f30000d2ee44b22c8ea919
44- ...expecting res=e229c19e791f2e41
45DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
46<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
47 auth_request_sent == 1
48 lu_result_sent == 0
49- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
50 rx from MS: pdisc=0x05 msg_type=0x54
51DREF IMSI:901700000010650: MSC conn use + 1 == 2
52DRLL Dispatching 04.08 message, pdisc=5
53DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
54DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
55DVLR SUBSCR(IMSI:901700000010650) received res: e2 29 c1 9e 79 1f 2e 41
56DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
57DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
58DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
59DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
60DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
61DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
62DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
63DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
64DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
65DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
66DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
67DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
68DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
69DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
70DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
71DVLR GSUP tx: 04010809710000000156f0
72GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
73DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
74DREF IMSI:901700000010650: MSC conn use - 1 == 1
75 lu_result_sent == 0
76- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
77<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
78DVLR GSUP rx 17: 10010809710000000156f00804032443f2
79DREF VLR subscr IMSI:901700000010650 usage increases to: 2
80DVLR IMSI:901700000010650 has MSISDN:42342
81DVLR GSUP tx: 12010809710000000156f0
82GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
83DREF VLR subscr MSISDN:42342 usage decreases to: 1
84<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
85 lu_result_sent == 0
86- HLR also sends GSUP _UPDATE_LOCATION_RESULT
87<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
88DVLR GSUP rx 11: 06010809710000000156f0
89DREF VLR subscr MSISDN:42342 usage increases to: 2
90DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
91DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
92DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
93DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
94DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
95DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
96DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
97DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
98DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
99DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
100DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
101DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
102DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
103DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
104DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
105DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
106DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
107DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
108DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
109DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
110DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
111DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
112- sending LU Accept for MSISDN:42342
113DREF VLR subscr MSISDN:42342 usage increases to: 3
114DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
115DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
116DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
117DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
118DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
119DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
120DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
121DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
122DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
123DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
124DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
125DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
126DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
127DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
128DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
129DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
130DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
131DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
132DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
133DREF MSISDN:42342: MSC conn use - 1 == 0
134DRLL subscr MSISDN:42342: Freeing subscriber connection
135DREF VLR subscr MSISDN:42342 usage decreases to: 2
136DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
137DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
138DREF VLR subscr MSISDN:42342 usage decreases to: 1
139<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
140- LU was successful, and the conn has already been closed
141 lu_result_sent == 1
142 llist_count(&net->subscr_conns) == 0
143---
144- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
145 rx from MS: pdisc=0x05 msg_type=0x24
146 new conn
147DREF unknown: MSC conn use + 1 == 1
148DRLL Dispatching 04.08 message, pdisc=5
149DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
150DREF unknown: MSC conn use + 1 == 2
151DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
152DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
153DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
154DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
155DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
156DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth (no Ciph)
157DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
158DREF VLR subscr MSISDN:42342 usage increases to: 2
159DREF VLR subscr MSISDN:42342 usage increases to: 3
160DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
161DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
162DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
163DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
164DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
165DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
166DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
167- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
168- ...rand=c187a53a5e6b9d573cac7c74451fd46d
169- ...autn=1843a645b98d00005b2d666af46c45d9
170- ...expecting res=7db47cf7f81e4dc7
171DREF VLR subscr MSISDN:42342 usage decreases to: 2
172DMM compl_l3: Keeping conn
173DREF MSISDN:42342: MSC conn use - 1 == 1
174 cm_service_result_sent == 0
175 auth_request_sent == 1
176- needs auth, not yet accepted
177msc_subscr_conn_is_accepted() == false
178 requests shall be thwarted
179DRLL Dispatching 04.08 message, pdisc=3
180DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
181DRLL Dispatching 04.08 message, pdisc=5
182DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
183DRLL Dispatching 04.08 message, pdisc=6
184DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
185DRLL Dispatching 04.08 message, pdisc=9
186DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
187- MS sends Authen Response, VLR accepts with a CM Service Accept
188 rx from MS: pdisc=0x05 msg_type=0x54
189DREF MSISDN:42342: MSC conn use + 1 == 2
190DRLL Dispatching 04.08 message, pdisc=5
191DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
192DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
193DVLR SUBSCR(MSISDN:42342) received res: 7d b4 7c f7 f8 1e 4d c7
194DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
195DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
196DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
197DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
198DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
199DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
200DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
201DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
202DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
203DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
204DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
205DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
206DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
207DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
208DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
209DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
210DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
211DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
212- sending CM Service Accept for MSISDN:42342
213DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
214DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
215DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
216DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
217DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
218DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
219DREF MSISDN:42342: MSC conn use - 1 == 1
220 cm_service_result_sent == 1
221- a USSD request is serviced
222 expecting USSD:
223 Your extension is 42342
224 rx from MS: pdisc=0x0b msg_type=0x3b
225DREF MSISDN:42342: MSC conn use + 1 == 2
226DRLL Dispatching 04.08 message, pdisc=11
227DMM MSISDN:42342 pdisc=11 msg_type=0x3b: received_cm_service_request changes to false
228DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
229DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
230DMM USSD: Own number requested
231DMM MSISDN:42342: MSISDN = 42342
232- DTAP --> MS: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
233- DTAP matches expected message
234DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
235DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
236DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
237DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
238DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
239DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
240DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
241DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
242DREF MSISDN:42342: MSC conn use - 1 == 1
243DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
244DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
245DREF MSISDN:42342: MSC conn use - 1 == 0
246DRLL subscr MSISDN:42342: Freeing subscriber connection
247DREF VLR subscr MSISDN:42342 usage decreases to: 1
248- all requests serviced, conn has been released
249 llist_count(&net->subscr_conns) == 0
250---
251- an SMS is sent, MS is paged
252DREF VLR subscr MSISDN:42342 usage increases to: 2
253 llist_count(&vsub->cs.requests) == 0
254DREF VLR subscr MSISDN:42342 usage increases to: 3
255DMM Subscriber MSISDN:42342 not paged yet.
Neels Hofmeyre2f24d52017-05-08 15:12:20 +0200[diff] [blame^]256 BTS/BSC sends out paging request to MSISDN:42342
257 strcmp(paging_expecting_imsi, vsub->imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]258DREF VLR subscr MSISDN:42342 usage increases to: 4
259 llist_count(&vsub->cs.requests) == 1
260DREF VLR subscr MSISDN:42342 usage decreases to: 3
261 paging_sent == 1
262 paging_stopped == 0
263- the subscriber and its pending request should remain
264DREF VLR subscr MSISDN:42342 usage increases to: 4
265 llist_count(&vsub->cs.requests) == 1
266DREF VLR subscr MSISDN:42342 usage decreases to: 3
267- MS replies with Paging Response, and VLR sends Auth Request with third key
268 rx from MS: pdisc=0x06 msg_type=0x27
269 new conn
270DREF unknown: MSC conn use + 1 == 1
271DRLL Dispatching 04.08 message, pdisc=6
272DRR PAGING RESPONSE: MI(IMSI)=901700000010650
273DREF unknown: MSC conn use + 1 == 2
274DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
275DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
276DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
277DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
278DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
279DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth (no Ciph)
280DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
281DREF VLR subscr MSISDN:42342 usage increases to: 4
282DREF VLR subscr MSISDN:42342 usage increases to: 5
283DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
284DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
285DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
286DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
287DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
288DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
289DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2
290- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
291- ...rand=efa9c29a9742148d5c9070348716e1bb
292- ...autn=f9375e6d41e1000096e7fe4ff1c27e39
293- ...expecting res=706f996719ba609c
294DREF VLR subscr MSISDN:42342 usage decreases to: 4
295DMM compl_l3: Keeping conn
296DREF MSISDN:42342: MSC conn use - 1 == 1
297 auth_request_sent == 1
298- needs auth, not yet accepted
299msc_subscr_conn_is_accepted() == false
300 requests shall be thwarted
301DRLL Dispatching 04.08 message, pdisc=3
302DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
303DRLL Dispatching 04.08 message, pdisc=5
304DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
305DRLL Dispatching 04.08 message, pdisc=6
306DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
307DRLL Dispatching 04.08 message, pdisc=9
308DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
309- MS sends Authen Response, VLR accepts and sends pending SMS
310 rx from MS: pdisc=0x05 msg_type=0x54
311DREF MSISDN:42342: MSC conn use + 1 == 2
312DRLL Dispatching 04.08 message, pdisc=5
313DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 706f996719ba609c)
314DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
315DVLR SUBSCR(MSISDN:42342) received res: 70 6f 99 67 19 ba 60 9c
316DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
317DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
318DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
319DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
320DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
321DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
322DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
323DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
324DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
325DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
326DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
327DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
328DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
329DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
330DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
331DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
332DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
333DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
334DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
335DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
336DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]337DREF VLR subscr MSISDN:42342 usage increases to: 5
338DREF MSISDN:42342: MSC conn use + 1 == 3
339- DTAP --> MS: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
340- DTAP matches expected message
341DREF VLR subscr MSISDN:42342 usage decreases to: 4
342DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
343DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
344DREF MSISDN:42342: MSC conn use - 1 == 2
345 dtap_tx_confirmed == 1
346 paging_stopped == 1
347- SMS was delivered, no requests pending for subscr
348DREF VLR subscr MSISDN:42342 usage increases to: 5
349 llist_count(&vsub->cs.requests) == 0
350DREF VLR subscr MSISDN:42342 usage decreases to: 4
351- conn is still open to wait for SMS ack dance
352 llist_count(&net->subscr_conns) == 1
353- MS replies with CP-ACK for received SMS
354 rx from MS: pdisc=0x89 msg_type=0x04
355DREF MSISDN:42342: MSC conn use + 1 == 3
356DRLL Dispatching 04.08 message, pdisc=9
357DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
358DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
359DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
360DREF MSISDN:42342: MSC conn use - 1 == 2
361 llist_count(&net->subscr_conns) == 1
362- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
363 rx from MS: pdisc=0x89 msg_type=0x01
364DREF MSISDN:42342: MSC conn use + 1 == 3
365DRLL Dispatching 04.08 message, pdisc=9
366DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
367- DTAP --> MS: 0904
368- DTAP matches expected message
369DREF VLR subscr MSISDN:42342 usage decreases to: 3
370DREF VLR subscr MSISDN:42342 usage decreases to: 2
371DREF MSISDN:42342: MSC conn use - 1 == 2
372DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
373DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
374DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
375DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
376DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
377DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
378DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
379DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
380DREF MSISDN:42342: MSC conn use - 1 == 1
381DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
382DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
383DREF MSISDN:42342: MSC conn use - 1 == 0
384DRLL subscr MSISDN:42342: Freeing subscriber connection
385DREF VLR subscr MSISDN:42342 usage decreases to: 1
386 dtap_tx_confirmed == 1
387- SMS is done, conn is gone
388 llist_count(&net->subscr_conns) == 0
389---
390- subscriber detaches
391 rx from MS: pdisc=0x05 msg_type=0x01
392 new conn
393DREF unknown: MSC conn use + 1 == 1
394DRLL Dispatching 04.08 message, pdisc=5
395DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
396DREF VLR subscr MSISDN:42342 usage increases to: 2
397DMM IMSI DETACH for MSISDN:42342
398DREF VLR subscr MSISDN:42342 usage decreases to: 1
399DREF VLR subscr MSISDN:42342 usage decreases to: 0
400DREF freeing VLR subscr MSISDN:42342
401DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
402DMM No conn_fsm, release conn
403DMM compl_l3: Discarding conn
404DRLL Freeing subscriber connection with NULL subscriber
405 llist_count(&net->subscr_conns) == 0
406===== test_umts_authen_geran: SUCCESS
407
408full talloc report on 'msgb' (total 0 bytes in 1 blocks)
409talloc_total_blocks(tall_bsc_ctx) == 75
410
411===== test_umts_authen_utran
412- Location Update request causes a GSUP Send Auth Info request to HLR
413 rx from MS: pdisc=0x05 msg_type=0x08
414 new conn
415DREF unknown: MSC conn use + 1 == 1
416DRLL Dispatching 04.08 message, pdisc=5
417DREF unknown: MSC conn use + 1 == 2
418DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
419DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
420DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
421DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
422DMM LU/new-LAC: 0/0
423DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
424DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
425DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth (no Ciph)
426DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
427DREF VLR subscr unknown usage increases to: 1
428DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
429DVLR New subscr, IMSI: 901700000010650
430DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]431DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]432DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
433DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
434DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
435DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
436DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
437DVLR GSUP tx: 08010809710000000156f0
438GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
439DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]440DMM compl_l3: Keeping conn
441DREF IMSI:901700000010650: MSC conn use - 1 == 1
442 lu_result_sent == 0
443- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
444<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
445DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
446DREF VLR subscr IMSI:901700000010650 usage increases to: 2
447DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
448DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
449DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
450DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
451- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
452- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
453- ...autn=8704f5ba55f30000d2ee44b22c8ea919
454- ...expecting res=e229c19e791f2e41
455DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
456<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
457 auth_request_sent == 1
458 lu_result_sent == 0
459- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
460 rx from MS: pdisc=0x05 msg_type=0x54
461DREF IMSI:901700000010650: MSC conn use + 1 == 2
462DRLL Dispatching 04.08 message, pdisc=5
463DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
464DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
465DVLR SUBSCR(IMSI:901700000010650) received res: e2 29 c1 9e 79 1f 2e 41
466DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
467DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
468DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
469DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
470DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
471DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
472DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
473DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
474DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
475DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
476DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
477DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
478DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
479DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
480DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
481DVLR GSUP tx: 04010809710000000156f0
482GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
483DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
484DREF IMSI:901700000010650: MSC conn use - 1 == 1
485 lu_result_sent == 0
486- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
487<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
488DVLR GSUP rx 17: 10010809710000000156f00804032443f2
489DREF VLR subscr IMSI:901700000010650 usage increases to: 2
490DVLR IMSI:901700000010650 has MSISDN:42342
491DVLR GSUP tx: 12010809710000000156f0
492GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
493DREF VLR subscr MSISDN:42342 usage decreases to: 1
494<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
495 lu_result_sent == 0
496- HLR also sends GSUP _UPDATE_LOCATION_RESULT
497<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
498DVLR GSUP rx 11: 06010809710000000156f0
499DREF VLR subscr MSISDN:42342 usage increases to: 2
500DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
501DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
502DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
503DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
504DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
505DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
506DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
507DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
508DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
509DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
510DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
511DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
512DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
513DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
514DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
515DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
516DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
517DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
518DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
519DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
520DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
521DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
522- sending LU Accept for MSISDN:42342
523DREF VLR subscr MSISDN:42342 usage increases to: 3
524DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
525DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
526DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
527DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
528DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
529DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
530DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
531DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
532DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
533DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
534DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
535DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
536DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
537DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
538DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
539DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
540DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
541DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
542DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
543DREF MSISDN:42342: MSC conn use - 1 == 0
544DRLL subscr MSISDN:42342: Freeing subscriber connection
545DREF VLR subscr MSISDN:42342 usage decreases to: 2
546DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
547DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
548DREF VLR subscr MSISDN:42342 usage decreases to: 1
549<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
550- LU was successful, and the conn has already been closed
551 lu_result_sent == 1
552 llist_count(&net->subscr_conns) == 0
553---
554- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
555 rx from MS: pdisc=0x05 msg_type=0x24
556 new conn
557DREF unknown: MSC conn use + 1 == 1
558DRLL Dispatching 04.08 message, pdisc=5
559DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
560DREF unknown: MSC conn use + 1 == 2
561DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
562DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
563DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
564DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
565DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
566DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth (no Ciph)
567DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
568DREF VLR subscr MSISDN:42342 usage increases to: 2
569DREF VLR subscr MSISDN:42342 usage increases to: 3
570DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
571DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
572DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
573DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
574DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
575DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
576DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
577- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
578- ...rand=c187a53a5e6b9d573cac7c74451fd46d
579- ...autn=1843a645b98d00005b2d666af46c45d9
580- ...expecting res=7db47cf7f81e4dc7
581DREF VLR subscr MSISDN:42342 usage decreases to: 2
582DMM compl_l3: Keeping conn
583DREF MSISDN:42342: MSC conn use - 1 == 1
584 cm_service_result_sent == 0
585 auth_request_sent == 1
586- needs auth, not yet accepted
587msc_subscr_conn_is_accepted() == false
588 requests shall be thwarted
589DRLL Dispatching 04.08 message, pdisc=3
590DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
591DRLL Dispatching 04.08 message, pdisc=5
592DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
593DRLL Dispatching 04.08 message, pdisc=6
594DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
595DRLL Dispatching 04.08 message, pdisc=9
596DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
597- MS sends Authen Response, VLR accepts with a CM Service Accept
598 rx from MS: pdisc=0x05 msg_type=0x54
599DREF MSISDN:42342: MSC conn use + 1 == 2
600DRLL Dispatching 04.08 message, pdisc=5
601DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
602DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
603DVLR SUBSCR(MSISDN:42342) received res: 7d b4 7c f7 f8 1e 4d c7
604DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
605DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
606DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
607DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
608DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
609DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
610DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
611DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
612DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
613DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
614DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
615DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
616DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
617DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
618DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
619DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
620DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
621DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
622- sending CM Service Accept for MSISDN:42342
623DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
624DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
625DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
626DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
627DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
628DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
629DREF MSISDN:42342: MSC conn use - 1 == 1
630 cm_service_result_sent == 1
631- a USSD request is serviced
632 expecting USSD:
633 Your extension is 42342
634 rx from MS: pdisc=0x0b msg_type=0x3b
635DREF MSISDN:42342: MSC conn use + 1 == 2
636DRLL Dispatching 04.08 message, pdisc=11
637DMM MSISDN:42342 pdisc=11 msg_type=0x3b: received_cm_service_request changes to false
638DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
639DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
640DMM USSD: Own number requested
641DMM MSISDN:42342: MSISDN = 42342
642- DTAP --> MS: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
643- DTAP matches expected message
644DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
645DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
646DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
647DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
648DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
649DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
650DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
651DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
652DREF MSISDN:42342: MSC conn use - 1 == 1
653DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
654DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
655DREF MSISDN:42342: MSC conn use - 1 == 0
656DRLL subscr MSISDN:42342: Freeing subscriber connection
657DREF VLR subscr MSISDN:42342 usage decreases to: 1
658- all requests serviced, conn has been released
659 llist_count(&net->subscr_conns) == 0
660---
661- an SMS is sent, MS is paged
662DREF VLR subscr MSISDN:42342 usage increases to: 2
663 llist_count(&vsub->cs.requests) == 0
664DREF VLR subscr MSISDN:42342 usage increases to: 3
665DMM Subscriber MSISDN:42342 not paged yet.
Neels Hofmeyre2f24d52017-05-08 15:12:20 +0200[diff] [blame^]666 BTS/BSC sends out paging request to MSISDN:42342
667 strcmp(paging_expecting_imsi, vsub->imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]668DREF VLR subscr MSISDN:42342 usage increases to: 4
669 llist_count(&vsub->cs.requests) == 1
670DREF VLR subscr MSISDN:42342 usage decreases to: 3
671 paging_sent == 1
672 paging_stopped == 0
673- the subscriber and its pending request should remain
674DREF VLR subscr MSISDN:42342 usage increases to: 4
675 llist_count(&vsub->cs.requests) == 1
676DREF VLR subscr MSISDN:42342 usage decreases to: 3
677- MS replies with Paging Response, and VLR sends Auth Request with third key
678 rx from MS: pdisc=0x06 msg_type=0x27
679 new conn
680DREF unknown: MSC conn use + 1 == 1
681DRLL Dispatching 04.08 message, pdisc=6
682DRR PAGING RESPONSE: MI(IMSI)=901700000010650
683DREF unknown: MSC conn use + 1 == 2
684DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
685DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
686DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
687DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
688DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
689DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth (no Ciph)
690DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
691DREF VLR subscr MSISDN:42342 usage increases to: 4
692DREF VLR subscr MSISDN:42342 usage increases to: 5
693DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
694DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
695DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
696DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
697DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
698DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
699DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2
700- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
701- ...rand=efa9c29a9742148d5c9070348716e1bb
702- ...autn=f9375e6d41e1000096e7fe4ff1c27e39
703- ...expecting res=706f996719ba609c
704DREF VLR subscr MSISDN:42342 usage decreases to: 4
705DMM compl_l3: Keeping conn
706DREF MSISDN:42342: MSC conn use - 1 == 1
707 auth_request_sent == 1
708- needs auth, not yet accepted
709msc_subscr_conn_is_accepted() == false
710 requests shall be thwarted
711DRLL Dispatching 04.08 message, pdisc=3
712DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
713DRLL Dispatching 04.08 message, pdisc=5
714DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
715DRLL Dispatching 04.08 message, pdisc=6
716DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
717DRLL Dispatching 04.08 message, pdisc=9
718DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
719- MS sends Authen Response, VLR accepts and sends pending SMS
720 rx from MS: pdisc=0x05 msg_type=0x54
721DREF MSISDN:42342: MSC conn use + 1 == 2
722DRLL Dispatching 04.08 message, pdisc=5
723DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 706f996719ba609c)
724DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
725DVLR SUBSCR(MSISDN:42342) received res: 70 6f 99 67 19 ba 60 9c
726DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
727DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
728DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
729DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
730DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
731DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
732DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
733DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
734DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
735DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
736DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
737DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
738DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
739DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
740DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
741DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
742DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
743DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
744DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
745DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
746DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]747DREF VLR subscr MSISDN:42342 usage increases to: 5
748DREF MSISDN:42342: MSC conn use + 1 == 3
749- DTAP --> MS: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
750- DTAP matches expected message
751DREF VLR subscr MSISDN:42342 usage decreases to: 4
752DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
753DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
754DREF MSISDN:42342: MSC conn use - 1 == 2
755 dtap_tx_confirmed == 1
756 paging_stopped == 1
757- SMS was delivered, no requests pending for subscr
758DREF VLR subscr MSISDN:42342 usage increases to: 5
759 llist_count(&vsub->cs.requests) == 0
760DREF VLR subscr MSISDN:42342 usage decreases to: 4
761- conn is still open to wait for SMS ack dance
762 llist_count(&net->subscr_conns) == 1
763- MS replies with CP-ACK for received SMS
764 rx from MS: pdisc=0x89 msg_type=0x04
765DREF MSISDN:42342: MSC conn use + 1 == 3
766DRLL Dispatching 04.08 message, pdisc=9
767DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
768DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
769DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
770DREF MSISDN:42342: MSC conn use - 1 == 2
771 llist_count(&net->subscr_conns) == 1
772- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
773 rx from MS: pdisc=0x89 msg_type=0x01
774DREF MSISDN:42342: MSC conn use + 1 == 3
775DRLL Dispatching 04.08 message, pdisc=9
776DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
777- DTAP --> MS: 0904
778- DTAP matches expected message
779DREF VLR subscr MSISDN:42342 usage decreases to: 3
780DREF VLR subscr MSISDN:42342 usage decreases to: 2
781DREF MSISDN:42342: MSC conn use - 1 == 2
782DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
783DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
784DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
785DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
786DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
787DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
788DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
789DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
790DREF MSISDN:42342: MSC conn use - 1 == 1
791DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
792DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
793DREF MSISDN:42342: MSC conn use - 1 == 0
794DRLL subscr MSISDN:42342: Freeing subscriber connection
795DREF VLR subscr MSISDN:42342 usage decreases to: 1
796 dtap_tx_confirmed == 1
797- SMS is done, conn is gone
798 llist_count(&net->subscr_conns) == 0
799---
800- subscriber detaches
801 rx from MS: pdisc=0x05 msg_type=0x01
802 new conn
803DREF unknown: MSC conn use + 1 == 1
804DRLL Dispatching 04.08 message, pdisc=5
805DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
806DREF VLR subscr MSISDN:42342 usage increases to: 2
807DMM IMSI DETACH for MSISDN:42342
808DREF VLR subscr MSISDN:42342 usage decreases to: 1
809DREF VLR subscr MSISDN:42342 usage decreases to: 0
810DREF freeing VLR subscr MSISDN:42342
811DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
812DMM No conn_fsm, release conn
813DMM compl_l3: Discarding conn
814DRLL Freeing subscriber connection with NULL subscriber
815 llist_count(&net->subscr_conns) == 0
816===== test_umts_authen_utran: SUCCESS
817
818full talloc report on 'msgb' (total 0 bytes in 1 blocks)
819talloc_total_blocks(tall_bsc_ctx) == 75
820
821===== test_umts_authen_resync_geran
822- Location Update request causes a GSUP Send Auth Info request to HLR
823 rx from MS: pdisc=0x05 msg_type=0x08
824 new conn
825DREF unknown: MSC conn use + 1 == 1
826DRLL Dispatching 04.08 message, pdisc=5
827DREF unknown: MSC conn use + 1 == 2
828DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
829DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
830DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
831DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
832DMM LU/new-LAC: 0/0
833DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
834DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
835DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth (no Ciph)
836DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
837DREF VLR subscr unknown usage increases to: 1
838DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
839DVLR New subscr, IMSI: 901700000010650
840DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]841DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]842DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
843DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
844DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
845DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
846DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
847DVLR GSUP tx: 08010809710000000156f0
848GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
849DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]850DMM compl_l3: Keeping conn
851DREF IMSI:901700000010650: MSC conn use - 1 == 1
852 lu_result_sent == 0
853- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
854<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
855DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
856DREF VLR subscr IMSI:901700000010650 usage increases to: 2
857DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
858DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples
859DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
860DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
861- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
862- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
863- ...autn=8704f5ba55f30000d2ee44b22c8ea919
864- ...expecting res=e229c19e791f2e41
865DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
866<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
867 auth_request_sent == 1
868 lu_result_sent == 0
869- MS sends Authen Failure with Resync cause, VLR sends GSUP to HLR to resync
870 rx from MS: pdisc=0x05 msg_type=0x1c
871DREF IMSI:901700000010650: MSC conn use + 1 == 2
872DRLL Dispatching 04.08 message, pdisc=5
873DMM IMSI:901700000010650: MM R99 AUTHENTICATION SYNCH (AUTS = 979498b1f72d3e28c59fa2e72f9c)
874DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_FAIL
875DVLR GSUP tx: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
876GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
877DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC
878DREF IMSI:901700000010650: MSC conn use - 1 == 1
879 gsup_tx_confirmed == 1
880 auth_request_sent == 0
881 lu_result_sent == 0
882- HLR replies with new tuples
883<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
884DVLR GSUP rx 211: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
885DREF VLR subscr IMSI:901700000010650 usage increases to: 2
886DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: Received Event VLR_AUTH_E_HLR_SAI_ACK
887DVLR SUBSCR(IMSI:901700000010650) Received 2 auth tuples
888DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: state_chg to VLR_SUB_AS_WAIT_RESP_RESYNC
889DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: got auth tuple: use_count=1 key_seq=0
890- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
891- ...rand=0f1feb1623e1bf626334e37ec448ac18
892- ...autn=02a83f62e9470000660d51afc75f169d
893- ...expecting res=1df5f0b4f22b696e
894DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
895<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
896 auth_request_sent == 1
897 lu_result_sent == 0
898- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
899 rx from MS: pdisc=0x05 msg_type=0x54
900DREF IMSI:901700000010650: MSC conn use + 1 == 2
901DRLL Dispatching 04.08 message, pdisc=5
902DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = 1df5f0b4f22b696e)
903DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Received Event VLR_AUTH_E_MS_AUTH_RESP
904DVLR SUBSCR(IMSI:901700000010650) received res: 1d f5 f0 b4 f2 2b 69 6e
905DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
906DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Authentication terminating with result VLR_AUTH_RES_PASSED
907DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: state_chg to VLR_SUB_AS_AUTHENTICATED
908DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
909DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
910DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
911DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
912DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
913DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
914DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
915DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
916DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
917DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
918DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
919DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
920DVLR GSUP tx: 04010809710000000156f0
921GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
922DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
923DREF IMSI:901700000010650: MSC conn use - 1 == 1
924 lu_result_sent == 0
925- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
926<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
927DVLR GSUP rx 17: 10010809710000000156f00804032443f2
928DREF VLR subscr IMSI:901700000010650 usage increases to: 2
929DVLR IMSI:901700000010650 has MSISDN:42342
930DVLR GSUP tx: 12010809710000000156f0
931GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
932DREF VLR subscr MSISDN:42342 usage decreases to: 1
933<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
934 lu_result_sent == 0
935- HLR also sends GSUP _UPDATE_LOCATION_RESULT
936<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
937DVLR GSUP rx 11: 06010809710000000156f0
938DREF VLR subscr MSISDN:42342 usage increases to: 2
939DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
940DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
941DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
942DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
943DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
944DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
945DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
946DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
947DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
948DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
949DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
950DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
951DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
952DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
953DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
954DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
955DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
956DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
957DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
958DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
959DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
960DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
961- sending LU Accept for MSISDN:42342
962DREF VLR subscr MSISDN:42342 usage increases to: 3
963DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
964DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
965DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
966DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
967DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
968DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
969DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
970DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
971DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
972DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
973DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
974DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
975DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
976DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
977DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
978DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
979DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
980DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
981DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
982DREF MSISDN:42342: MSC conn use - 1 == 0
983DRLL subscr MSISDN:42342: Freeing subscriber connection
984DREF VLR subscr MSISDN:42342 usage decreases to: 2
985DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
986DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
987DREF VLR subscr MSISDN:42342 usage decreases to: 1
988<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
989- LU was successful, and the conn has already been closed
990 lu_result_sent == 1
991 llist_count(&net->subscr_conns) == 0
992DREF freeing VLR subscr MSISDN:42342
993===== test_umts_authen_resync_geran: SUCCESS
994
995full talloc report on 'msgb' (total 0 bytes in 1 blocks)
996talloc_total_blocks(tall_bsc_ctx) == 75
997
998===== test_umts_authen_resync_utran
999- Location Update request causes a GSUP Send Auth Info request to HLR
1000 rx from MS: pdisc=0x05 msg_type=0x08
1001 new conn
1002DREF unknown: MSC conn use + 1 == 1
1003DRLL Dispatching 04.08 message, pdisc=5
1004DREF unknown: MSC conn use + 1 == 2
1005DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1006DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1007DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1008DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1009DMM LU/new-LAC: 0/0
1010DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1011DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1012DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth (no Ciph)
1013DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1014DREF VLR subscr unknown usage increases to: 1
1015DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1016DVLR New subscr, IMSI: 901700000010650
1017DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]1018DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1019DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1020DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1021DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1022DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1023DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1024DVLR GSUP tx: 08010809710000000156f0
1025GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1026DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1027DMM compl_l3: Keeping conn
1028DREF IMSI:901700000010650: MSC conn use - 1 == 1
1029 lu_result_sent == 0
1030- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1031<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
1032DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
1033DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1034DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1035DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples
1036DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
1037DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
1038- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1039- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1040- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1041- ...expecting res=e229c19e791f2e41
1042DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1043<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1044 auth_request_sent == 1
1045 lu_result_sent == 0
1046- MS sends Authen Failure with Resync cause, VLR sends GSUP to HLR to resync
1047 rx from MS: pdisc=0x05 msg_type=0x1c
1048DREF IMSI:901700000010650: MSC conn use + 1 == 2
1049DRLL Dispatching 04.08 message, pdisc=5
1050DMM IMSI:901700000010650: MM R99 AUTHENTICATION SYNCH (AUTS = 979498b1f72d3e28c59fa2e72f9c)
1051DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_FAIL
1052DVLR GSUP tx: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
1053GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
1054DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC
1055DREF IMSI:901700000010650: MSC conn use - 1 == 1
1056 gsup_tx_confirmed == 1
1057 auth_request_sent == 0
1058 lu_result_sent == 0
1059- HLR replies with new tuples
1060<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
1061DVLR GSUP rx 211: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
1062DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1063DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1064DVLR SUBSCR(IMSI:901700000010650) Received 2 auth tuples
1065DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: state_chg to VLR_SUB_AS_WAIT_RESP_RESYNC
1066DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: got auth tuple: use_count=1 key_seq=0
1067- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1068- ...rand=0f1feb1623e1bf626334e37ec448ac18
1069- ...autn=02a83f62e9470000660d51afc75f169d
1070- ...expecting res=1df5f0b4f22b696e
1071DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1072<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1073 auth_request_sent == 1
1074 lu_result_sent == 0
1075- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
1076 rx from MS: pdisc=0x05 msg_type=0x54
1077DREF IMSI:901700000010650: MSC conn use + 1 == 2
1078DRLL Dispatching 04.08 message, pdisc=5
1079DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = 1df5f0b4f22b696e)
1080DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Received Event VLR_AUTH_E_MS_AUTH_RESP
1081DVLR SUBSCR(IMSI:901700000010650) received res: 1d f5 f0 b4 f2 2b 69 6e
1082DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
1083DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Authentication terminating with result VLR_AUTH_RES_PASSED
1084DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: state_chg to VLR_SUB_AS_AUTHENTICATED
1085DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1086DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
1087DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1088DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1089DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1090DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1091DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1092DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1093DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1094DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1095DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1096DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1097DVLR GSUP tx: 04010809710000000156f0
1098GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
1099DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1100DREF IMSI:901700000010650: MSC conn use - 1 == 1
1101 lu_result_sent == 0
1102- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1103<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1104DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1105DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1106DVLR IMSI:901700000010650 has MSISDN:42342
1107DVLR GSUP tx: 12010809710000000156f0
1108GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1109DREF VLR subscr MSISDN:42342 usage decreases to: 1
1110<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1111 lu_result_sent == 0
1112- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1113<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1114DVLR GSUP rx 11: 06010809710000000156f0
1115DREF VLR subscr MSISDN:42342 usage increases to: 2
1116DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1117DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1118DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1119DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1120DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1121DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1122DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1123DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1124DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1125DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1126DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1127DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1128DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1129DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1130DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
1131DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1132DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1133DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1134DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
1135DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1136DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1137DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1138- sending LU Accept for MSISDN:42342
1139DREF VLR subscr MSISDN:42342 usage increases to: 3
1140DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1141DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1142DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1143DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1144DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1145DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1146DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1147DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1148DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1149DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1150DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1151DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1152DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1153DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1154DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1155DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1156DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1157DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1158DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
1159DREF MSISDN:42342: MSC conn use - 1 == 0
1160DRLL subscr MSISDN:42342: Freeing subscriber connection
1161DREF VLR subscr MSISDN:42342 usage decreases to: 2
1162DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1163DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1164DREF VLR subscr MSISDN:42342 usage decreases to: 1
1165<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1166- LU was successful, and the conn has already been closed
1167 lu_result_sent == 1
1168 llist_count(&net->subscr_conns) == 0
1169DREF freeing VLR subscr MSISDN:42342
1170===== test_umts_authen_resync_utran: SUCCESS
1171
1172full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1173talloc_total_blocks(tall_bsc_ctx) == 75
1174
1175full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1176talloc_total_blocks(tall_bsc_ctx) == 9
1177