Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / 54a706cf920d1b5dcfbd5a4697538d16ea18aa98 / . / tests / msc_vlr / msc_vlr_test_gsm_authen.err
blob: 09ff4aea6fb786b34d9a85c51ac780dae2edd093 [file] [log] [blame]
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1===== test_gsm_authen
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(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
9DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
10DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
11DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
12DMM LU/new-LAC: 1/0
13DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
14DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
15DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
16DVLR vlr_lu_fsm(901700000004620){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=901700000004620 id=901700000004620
19DVLR New subscr, IMSI: 901700000004620
20DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame^]21DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]22DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
23DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
24DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
25DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
26DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
27DVLR GSUP tx: 08010809710000004026f0
28GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
29DVLR VLR_Authenticate(901700000004620){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:901700000004620: 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: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
35DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
36DREF VLR subscr IMSI:901700000004620 usage increases to: 2
37DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
38DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
39DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
40DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
41- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
42- ...rand=585df1ae287f6e273dce07090d61320b
43- ...expecting sres=2d8b2c3e
44DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
45<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
46 auth_request_sent == 1
47 lu_result_sent == 0
48- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
49<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
50DVLR GSUP rx 11: 06010809710000004026f0
51DREF VLR subscr IMSI:901700000004620 usage increases to: 2
52DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
53DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
54DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
55<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
56msc_subscr_conn_is_accepted() == false
57 requests shall be thwarted
58DRLL Dispatching 04.08 message, pdisc=3
59DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
60DRLL Dispatching 04.08 message, pdisc=5
61DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
62DRLL Dispatching 04.08 message, pdisc=6
63DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
64DRLL Dispatching 04.08 message, pdisc=9
65DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
66 lu_result_sent == 0
67- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
68 rx from MS: pdisc=0x05 msg_type=0x54
69DREF IMSI:901700000004620: MSC conn use + 1 == 2
70DRLL Dispatching 04.08 message, pdisc=5
71DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
72DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
73DVLR SUBSCR(IMSI:901700000004620) received res: 2d 8b 2c 3e
74DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
75DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
76DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
77DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
78DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
79DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
80DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
81DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
82DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
83DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
84DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
85DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
86DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
87DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
88DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
89DVLR GSUP tx: 04010809710000004026f0
90GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
91DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
92DREF IMSI:901700000004620: MSC conn use - 1 == 1
93 lu_result_sent == 0
94- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
95<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
96DVLR GSUP rx 17: 10010809710000004026f00804036470f1
97DREF VLR subscr IMSI:901700000004620 usage increases to: 2
98DVLR IMSI:901700000004620 has MSISDN:46071
99DVLR GSUP tx: 12010809710000004026f0
100GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
101DREF VLR subscr MSISDN:46071 usage decreases to: 1
102<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
103 lu_result_sent == 0
104- HLR also sends GSUP _UPDATE_LOCATION_RESULT
105<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
106DVLR GSUP rx 11: 06010809710000004026f0
107DREF VLR subscr MSISDN:46071 usage increases to: 2
108DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
109DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
110DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
111DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
112DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
113DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
114DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
115DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
116DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
117DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
118DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
119DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
120DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
121DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
122DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
123DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
124DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
125DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
126DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
127DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
128DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
129DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
130- sending LU Accept for MSISDN:46071
131DREF VLR subscr MSISDN:46071 usage increases to: 3
132DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
133DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
134DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
135DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
136DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
137DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
138DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
139DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
140DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
141DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
142DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
143DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
144DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
145DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
146DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
147DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
148DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
149DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
150DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
151DREF MSISDN:46071: MSC conn use - 1 == 0
152DRLL subscr MSISDN:46071: Freeing subscriber connection
153DREF VLR subscr MSISDN:46071 usage decreases to: 2
154DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
155DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
156DREF VLR subscr MSISDN:46071 usage decreases to: 1
157<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
158- LU was successful, and the conn has already been closed
159 lu_result_sent == 1
160 llist_count(&net->subscr_conns) == 0
161---
162- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
163 rx from MS: pdisc=0x05 msg_type=0x24
164 new conn
165DREF unknown: MSC conn use + 1 == 1
166DRLL Dispatching 04.08 message, pdisc=5
167DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
168DREF unknown: MSC conn use + 1 == 2
169DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
170DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
171DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
172DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
173DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
174DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
175DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
176DREF VLR subscr MSISDN:46071 usage increases to: 2
177DREF VLR subscr MSISDN:46071 usage increases to: 3
178DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
179DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
180DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
181DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000004620)
182DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
183DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
184DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
185- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
186- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
187- ...expecting sres=20bde240
188DREF VLR subscr MSISDN:46071 usage decreases to: 2
189DMM compl_l3: Keeping conn
190DREF MSISDN:46071: MSC conn use - 1 == 1
191 cm_service_result_sent == 0
192 auth_request_sent == 1
193- needs auth, not yet accepted
194msc_subscr_conn_is_accepted() == false
195 requests shall be thwarted
196DRLL Dispatching 04.08 message, pdisc=3
197DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
198DRLL Dispatching 04.08 message, pdisc=5
199DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
200DRLL Dispatching 04.08 message, pdisc=6
201DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
202DRLL Dispatching 04.08 message, pdisc=9
203DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
204- MS sends Authen Response, VLR accepts with a CM Service Accept
205 rx from MS: pdisc=0x05 msg_type=0x54
206DREF MSISDN:46071: MSC conn use + 1 == 2
207DRLL Dispatching 04.08 message, pdisc=5
208DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
209DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
210DVLR SUBSCR(MSISDN:46071) received res: 20 bd e2 40
211DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
212DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
213DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
214DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
215DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000004620)
216DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
217DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
218DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
219DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
220DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
221DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
222DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
223DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
224DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
225DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
226DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
227DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
228DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
229- sending CM Service Accept for MSISDN:46071
230DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
231DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
232DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
233DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
234DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
235DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
236DREF MSISDN:46071: MSC conn use - 1 == 1
237 cm_service_result_sent == 1
238- a USSD request is serviced
239 expecting USSD:
240 Your extension is 46071
241 rx from MS: pdisc=0x0b msg_type=0x3b
242DREF MSISDN:46071: MSC conn use + 1 == 2
243DRLL Dispatching 04.08 message, pdisc=11
244DMM MSISDN:46071 pdisc=11 msg_type=0x3b: received_cm_service_request changes to false
245DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
246DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
247DMM USSD: Own number requested
248DMM MSISDN:46071: MSISDN = 46071
249- DTAP --> MS: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
250- DTAP matches expected message
251DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
252DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
253DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
254DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
255DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
256DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
257DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
258DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
259DREF MSISDN:46071: MSC conn use - 1 == 1
260DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
261DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
262DREF MSISDN:46071: MSC conn use - 1 == 0
263DRLL subscr MSISDN:46071: Freeing subscriber connection
264DREF VLR subscr MSISDN:46071 usage decreases to: 1
265- all requests serviced, conn has been released
266 llist_count(&net->subscr_conns) == 0
267---
268- an SMS is sent, MS is paged
269DREF VLR subscr MSISDN:46071 usage increases to: 2
270 llist_count(&vsub->cs.requests) == 0
271DREF VLR subscr MSISDN:46071 usage increases to: 3
272DMM Subscriber MSISDN:46071 not paged yet.
273 BTS/BSC sends out paging request to IMSI:901700000004620 for channel type 1
274 strcmp(paging_expecting_imsi, sub->imsi) == 0
275DREF BSC subscr IMSI:901700000004620 usage decreases to: 0
276DREF VLR subscr MSISDN:46071 usage increases to: 4
277 llist_count(&vsub->cs.requests) == 1
278DREF VLR subscr MSISDN:46071 usage decreases to: 3
279 paging_sent == 1
280 paging_stopped == 0
281- the subscriber and its pending request should remain
282DREF VLR subscr MSISDN:46071 usage increases to: 4
283 llist_count(&vsub->cs.requests) == 1
284DREF VLR subscr MSISDN:46071 usage decreases to: 3
285- MS replies with Paging Response, and VLR sends Auth Request with third key
286 rx from MS: pdisc=0x06 msg_type=0x27
287 new conn
288DREF unknown: MSC conn use + 1 == 1
289DRLL Dispatching 04.08 message, pdisc=6
290DRR PAGING RESPONSE: MI(IMSI)=901700000004620
291DREF unknown: MSC conn use + 1 == 2
292DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
293DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
294DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
295DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
296DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
297DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
298DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
299DREF VLR subscr MSISDN:46071 usage increases to: 4
300DREF VLR subscr MSISDN:46071 usage increases to: 5
301DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
302DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
303DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
304DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000004620)
305DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
306DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
307DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2
308- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
309- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
310- ...expecting sres=a29514ae
311DREF VLR subscr MSISDN:46071 usage decreases to: 4
312DMM compl_l3: Keeping conn
313DREF MSISDN:46071: MSC conn use - 1 == 1
314 auth_request_sent == 1
315- needs auth, not yet accepted
316msc_subscr_conn_is_accepted() == false
317 requests shall be thwarted
318DRLL Dispatching 04.08 message, pdisc=3
319DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
320DRLL Dispatching 04.08 message, pdisc=5
321DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
322DRLL Dispatching 04.08 message, pdisc=6
323DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
324DRLL Dispatching 04.08 message, pdisc=9
325DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
326- MS sends Authen Response, VLR accepts and sends pending SMS
327 rx from MS: pdisc=0x05 msg_type=0x54
328DREF MSISDN:46071: MSC conn use + 1 == 2
329DRLL Dispatching 04.08 message, pdisc=5
330DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
331DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
332DVLR SUBSCR(MSISDN:46071) received res: a2 95 14 ae
333DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
334DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
335DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
336DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
337DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000004620)
338DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
339DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
340DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
341DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
342DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
343DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
344DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
345DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
346DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
347DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
348DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
349DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
350DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
351DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
352DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
353DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
354DREF BSC subscr IMSI:901700000004620 usage decreases to: 0
355DREF VLR subscr MSISDN:46071 usage increases to: 5
356DREF MSISDN:46071: MSC conn use + 1 == 3
357- DTAP --> MS: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
358- DTAP matches expected message
359DREF VLR subscr MSISDN:46071 usage decreases to: 4
360DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
361DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
362DREF MSISDN:46071: MSC conn use - 1 == 2
363 dtap_tx_confirmed == 1
364 paging_stopped == 1
365- SMS was delivered, no requests pending for subscr
366DREF VLR subscr MSISDN:46071 usage increases to: 5
367 llist_count(&vsub->cs.requests) == 0
368DREF VLR subscr MSISDN:46071 usage decreases to: 4
369- conn is still open to wait for SMS ack dance
370 llist_count(&net->subscr_conns) == 1
371- MS replies with CP-ACK for received SMS
372 rx from MS: pdisc=0x89 msg_type=0x04
373DREF MSISDN:46071: MSC conn use + 1 == 3
374DRLL Dispatching 04.08 message, pdisc=9
375DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
376DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
377DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
378DREF MSISDN:46071: MSC conn use - 1 == 2
379 llist_count(&net->subscr_conns) == 1
380- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
381 rx from MS: pdisc=0x89 msg_type=0x01
382DREF MSISDN:46071: MSC conn use + 1 == 3
383DRLL Dispatching 04.08 message, pdisc=9
384DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
385- DTAP --> MS: 0904
386- DTAP matches expected message
387DREF VLR subscr MSISDN:46071 usage decreases to: 3
388DREF VLR subscr MSISDN:46071 usage decreases to: 2
389DREF MSISDN:46071: MSC conn use - 1 == 2
390DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
391DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
392DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
393DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
394DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
395DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
396DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
397DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
398DREF MSISDN:46071: MSC conn use - 1 == 1
399DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
400DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
401DREF MSISDN:46071: MSC conn use - 1 == 0
402DRLL subscr MSISDN:46071: Freeing subscriber connection
403DREF VLR subscr MSISDN:46071 usage decreases to: 1
404 dtap_tx_confirmed == 1
405- SMS is done, conn is gone
406 llist_count(&net->subscr_conns) == 0
407---
408- subscriber detaches
409 rx from MS: pdisc=0x05 msg_type=0x01
410 new conn
411DREF unknown: MSC conn use + 1 == 1
412DRLL Dispatching 04.08 message, pdisc=5
413DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
414DREF VLR subscr MSISDN:46071 usage increases to: 2
415DMM IMSI DETACH for MSISDN:46071
416DREF VLR subscr MSISDN:46071 usage decreases to: 1
417DREF VLR subscr MSISDN:46071 usage decreases to: 0
418DREF freeing VLR subscr MSISDN:46071
419DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
420DMM No conn_fsm, release conn
421DMM compl_l3: Discarding conn
422DRLL Freeing subscriber connection with NULL subscriber
423 llist_count(&net->subscr_conns) == 0
424===== test_gsm_authen: SUCCESS
425
426full talloc report on 'msgb' (total 0 bytes in 1 blocks)
427talloc_total_blocks(tall_bsc_ctx) == 75
428
429===== test_gsm_authen_tmsi
430- Location Update request causes a GSUP Send Auth Info request to HLR
431 rx from MS: pdisc=0x05 msg_type=0x08
432 new conn
433DREF unknown: MSC conn use + 1 == 1
434DRLL Dispatching 04.08 message, pdisc=5
435DREF unknown: MSC conn use + 1 == 2
436DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
437DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
438DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
439DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
440DMM LU/new-LAC: 1/0
441DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
442DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
443DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
444DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
445DREF VLR subscr unknown usage increases to: 1
446DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
447DVLR New subscr, IMSI: 901700000004620
448DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame^]449DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]450DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
451DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
452DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
453DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
454DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
455DVLR GSUP tx: 08010809710000004026f0
456GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
457DVLR VLR_Authenticate(901700000004620){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]458DMM compl_l3: Keeping conn
459DREF IMSI:901700000004620: MSC conn use - 1 == 1
460 lu_result_sent == 0
461- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
462<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
463DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
464DREF VLR subscr IMSI:901700000004620 usage increases to: 2
465DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
466DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
467DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
468DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
469- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
470- ...rand=585df1ae287f6e273dce07090d61320b
471- ...expecting sres=2d8b2c3e
472DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
473<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
474 auth_request_sent == 1
475 lu_result_sent == 0
476- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
477<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
478DVLR GSUP rx 11: 06010809710000004026f0
479DREF VLR subscr IMSI:901700000004620 usage increases to: 2
480DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
481DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
482DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
483<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
484msc_subscr_conn_is_accepted() == false
485 requests shall be thwarted
486DRLL Dispatching 04.08 message, pdisc=3
487DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
488DRLL Dispatching 04.08 message, pdisc=5
489DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
490DRLL Dispatching 04.08 message, pdisc=6
491DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
492DRLL Dispatching 04.08 message, pdisc=9
493DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
494 lu_result_sent == 0
495- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
496 rx from MS: pdisc=0x05 msg_type=0x54
497DREF IMSI:901700000004620: MSC conn use + 1 == 2
498DRLL Dispatching 04.08 message, pdisc=5
499DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
500DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
501DVLR SUBSCR(IMSI:901700000004620) received res: 2d 8b 2c 3e
502DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
503DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
504DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
505DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
506DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
507DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
508DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
509DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
510DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
511DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
512DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
513DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
514DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
515DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
516DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
517DVLR GSUP tx: 04010809710000004026f0
518GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
519DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
520DREF IMSI:901700000004620: MSC conn use - 1 == 1
521 lu_result_sent == 0
522- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
523<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
524DVLR GSUP rx 17: 10010809710000004026f00804036470f1
525DREF VLR subscr IMSI:901700000004620 usage increases to: 2
526DVLR IMSI:901700000004620 has MSISDN:46071
527DVLR GSUP tx: 12010809710000004026f0
528GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
529DREF VLR subscr MSISDN:46071 usage decreases to: 1
530<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
531 lu_result_sent == 0
532- HLR also sends GSUP _UPDATE_LOCATION_RESULT
533<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
534DVLR GSUP rx 11: 06010809710000004026f0
535DREF VLR subscr MSISDN:46071 usage increases to: 2
536DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
537DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
538DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
539DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
540DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
541DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
542DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
543DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
544DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
545DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
546DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
547DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
548DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
549DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
550DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
551DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
552DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
553DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
554DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
555DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
556DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
557DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
558DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
559DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
560- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
561DREF VLR subscr MSISDN:46071 usage decreases to: 1
562<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
563- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
564 llist_count(&net->subscr_conns) == 1
565 lu_result_sent == 1
566msc_subscr_conn_is_accepted() == false
567 requests shall be thwarted
568DRLL Dispatching 04.08 message, pdisc=3
569DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
570DRLL Dispatching 04.08 message, pdisc=5
571DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
572DRLL Dispatching 04.08 message, pdisc=6
573DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
574DRLL Dispatching 04.08 message, pdisc=9
575DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
576- even though the TMSI is not acked, we can already find the subscr with it
577DREF VLR subscr MSISDN:46071 usage increases to: 2
578 vsub != NULL == 1
579 strcmp(vsub->imsi, imsi) == 0
580 vsub->tmsi_new == 0x03020100
581 vsub->tmsi == 0xffffffff
582DREF VLR subscr MSISDN:46071 usage decreases to: 1
583- MS sends TMSI Realloc Complete
584 rx from MS: pdisc=0x05 msg_type=0x5b
585DREF MSISDN:46071: MSC conn use + 1 == 2
586DRLL Dispatching 04.08 message, pdisc=5
587DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
588DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
589DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
590DREF VLR subscr MSISDN:46071 usage increases to: 2
591DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
592DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
593DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
594DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
595DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
596DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
597DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
598DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
599DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
600DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
601DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
602DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
603DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
604DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
605DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
606DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
607DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
608DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
609DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
610DREF MSISDN:46071: MSC conn use - 1 == 1
611DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
612DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
613DREF MSISDN:46071: MSC conn use - 1 == 0
614DRLL subscr MSISDN:46071: Freeing subscriber connection
615DREF VLR subscr MSISDN:46071 usage decreases to: 1
616- LU was successful, and the conn has already been closed
617 llist_count(&net->subscr_conns) == 0
618- Subscriber has the new TMSI
619DREF VLR subscr MSISDN:46071 usage increases to: 2
620 vsub != NULL == 1
621 strcmp(vsub->imsi, imsi) == 0
622 vsub->tmsi_new == 0xffffffff
623 vsub->tmsi == 0x03020100
624DREF VLR subscr MSISDN:46071 usage decreases to: 1
625---
626- after a while, a new conn sends a CM Service Request using above TMSI. VLR responds with Auth Req, 2nd auth vector
627 rx from MS: pdisc=0x05 msg_type=0x24
628 new conn
629DREF unknown: MSC conn use + 1 == 1
630DRLL Dispatching 04.08 message, pdisc=5
631DMM <- CM SERVICE REQUEST serv_type=0x08 MI(TMSI)=50462976
632DREF unknown: MSC conn use + 1 == 2
633DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
634DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
635DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
636DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
637DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
638DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
639DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
640DREF VLR subscr MSISDN:46071 usage increases to: 2
641DREF VLR subscr MSISDN:46071 usage increases to: 3
642DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
643DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
644DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
645DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(50462976)
646DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
647DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
648DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
649- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
650- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
651- ...expecting sres=20bde240
652DREF VLR subscr MSISDN:46071 usage decreases to: 2
653DMM compl_l3: Keeping conn
654DREF MSISDN:46071: MSC conn use - 1 == 1
655 cm_service_result_sent == 0
656 auth_request_sent == 1
657- needs auth, not yet accepted
658msc_subscr_conn_is_accepted() == false
659 requests shall be thwarted
660DRLL Dispatching 04.08 message, pdisc=3
661DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
662DRLL Dispatching 04.08 message, pdisc=5
663DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
664DRLL Dispatching 04.08 message, pdisc=6
665DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
666DRLL Dispatching 04.08 message, pdisc=9
667DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
668- MS sends Authen Response, VLR accepts with a CM Service Accept
669 rx from MS: pdisc=0x05 msg_type=0x54
670DREF MSISDN:46071: MSC conn use + 1 == 2
671DRLL Dispatching 04.08 message, pdisc=5
672DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
673DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
674DVLR SUBSCR(MSISDN:46071) received res: 20 bd e2 40
675DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
676DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
677DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
678DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
679DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(50462976)
680DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
681DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
682DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
683DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
684DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
685DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
686DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
687DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
688DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
689DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
690DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
691DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
692DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
693- sending CM Service Accept for MSISDN:46071
694DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
695DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
696DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
697DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
698DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
699DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
700DREF MSISDN:46071: MSC conn use - 1 == 1
701 cm_service_result_sent == 1
702- a USSD request is serviced
703 expecting USSD:
704 Your extension is 46071
705 rx from MS: pdisc=0x0b msg_type=0x3b
706DREF MSISDN:46071: MSC conn use + 1 == 2
707DRLL Dispatching 04.08 message, pdisc=11
708DMM MSISDN:46071 pdisc=11 msg_type=0x3b: received_cm_service_request changes to false
709DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
710DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
711DMM USSD: Own number requested
712DMM MSISDN:46071: MSISDN = 46071
713- DTAP --> MS: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
714- DTAP matches expected message
715DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
716DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
717DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
718DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
719DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
720DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
721DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
722DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
723DREF MSISDN:46071: MSC conn use - 1 == 1
724DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
725DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
726DREF MSISDN:46071: MSC conn use - 1 == 0
727DRLL subscr MSISDN:46071: Freeing subscriber connection
728DREF VLR subscr MSISDN:46071 usage decreases to: 1
729- all requests serviced, conn has been released
730 llist_count(&net->subscr_conns) == 0
731---
732- an SMS is sent, MS is paged
733DREF VLR subscr MSISDN:46071 usage increases to: 2
734 llist_count(&vsub->cs.requests) == 0
735DREF VLR subscr MSISDN:46071 usage increases to: 3
736DMM Subscriber MSISDN:46071 not paged yet.
737 BTS/BSC sends out paging request to IMSI:901700000004620 for channel type 1
738 paging_expecting_tmsi == 0x03020100
739DREF BSC subscr IMSI:901700000004620 usage decreases to: 0
740DREF VLR subscr MSISDN:46071 usage increases to: 4
741 llist_count(&vsub->cs.requests) == 1
742DREF VLR subscr MSISDN:46071 usage decreases to: 3
743 paging_sent == 1
744 paging_stopped == 0
745- the subscriber and its pending request should remain
746DREF VLR subscr MSISDN:46071 usage increases to: 4
747 llist_count(&vsub->cs.requests) == 1
748DREF VLR subscr MSISDN:46071 usage decreases to: 3
749- MS replies with Paging Response using TMSI, and VLR sends Auth Request with third key
750 rx from MS: pdisc=0x06 msg_type=0x27
751 new conn
752DREF unknown: MSC conn use + 1 == 1
753DRLL Dispatching 04.08 message, pdisc=6
754DRR PAGING RESPONSE: MI(TMSI)=50462976
755DREF unknown: MSC conn use + 1 == 2
756DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
757DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
758DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
759DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
760DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
761DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
762DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
763DREF VLR subscr MSISDN:46071 usage increases to: 4
764DREF VLR subscr MSISDN:46071 usage increases to: 5
765DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
766DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
767DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
768DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(50462976)
769DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
770DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
771DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2
772- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
773- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
774- ...expecting sres=a29514ae
775DREF VLR subscr MSISDN:46071 usage decreases to: 4
776DMM compl_l3: Keeping conn
777DREF MSISDN:46071: MSC conn use - 1 == 1
778 auth_request_sent == 1
779- needs auth, not yet accepted
780msc_subscr_conn_is_accepted() == false
781 requests shall be thwarted
782DRLL Dispatching 04.08 message, pdisc=3
783DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
784DRLL Dispatching 04.08 message, pdisc=5
785DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
786DRLL Dispatching 04.08 message, pdisc=6
787DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
788DRLL Dispatching 04.08 message, pdisc=9
789DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
790- MS sends Authen Response, VLR accepts and sends pending SMS
791 rx from MS: pdisc=0x05 msg_type=0x54
792DREF MSISDN:46071: MSC conn use + 1 == 2
793DRLL Dispatching 04.08 message, pdisc=5
794DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
795DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
796DVLR SUBSCR(MSISDN:46071) received res: a2 95 14 ae
797DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
798DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
799DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
800DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
801DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(50462976)
802DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
803DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
804DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
805DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
806DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
807DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
808DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
809DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
810DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
811DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
812DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
813DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
814DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
815DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
816DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
817DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
818DREF BSC subscr IMSI:901700000004620 usage decreases to: 0
819DREF VLR subscr MSISDN:46071 usage increases to: 5
820DREF MSISDN:46071: MSC conn use + 1 == 3
821- DTAP --> MS: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
822- DTAP matches expected message
823DREF VLR subscr MSISDN:46071 usage decreases to: 4
824DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
825DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
826DREF MSISDN:46071: MSC conn use - 1 == 2
827 dtap_tx_confirmed == 1
828 paging_stopped == 1
829- SMS was delivered, no requests pending for subscr
830DREF VLR subscr MSISDN:46071 usage increases to: 5
831 llist_count(&vsub->cs.requests) == 0
832DREF VLR subscr MSISDN:46071 usage decreases to: 4
833- conn is still open to wait for SMS ack dance
834 llist_count(&net->subscr_conns) == 1
835- MS replies with CP-ACK for received SMS
836 rx from MS: pdisc=0x89 msg_type=0x04
837DREF MSISDN:46071: MSC conn use + 1 == 3
838DRLL Dispatching 04.08 message, pdisc=9
839DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
840DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
841DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
842DREF MSISDN:46071: MSC conn use - 1 == 2
843 llist_count(&net->subscr_conns) == 1
844- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
845 rx from MS: pdisc=0x89 msg_type=0x01
846DREF MSISDN:46071: MSC conn use + 1 == 3
847DRLL Dispatching 04.08 message, pdisc=9
848DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
849- DTAP --> MS: 0904
850- DTAP matches expected message
851DREF VLR subscr MSISDN:46071 usage decreases to: 3
852DREF VLR subscr MSISDN:46071 usage decreases to: 2
853DREF MSISDN:46071: MSC conn use - 1 == 2
854DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
855DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
856DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
857DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
858DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
859DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
860DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
861DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
862DREF MSISDN:46071: MSC conn use - 1 == 1
863DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
864DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
865DREF MSISDN:46071: MSC conn use - 1 == 0
866DRLL subscr MSISDN:46071: Freeing subscriber connection
867DREF VLR subscr MSISDN:46071 usage decreases to: 1
868 dtap_tx_confirmed == 1
869- SMS is done, conn is gone
870 llist_count(&net->subscr_conns) == 0
871---
872- subscriber sends LU Request, this time with the TMSI
873- Location Update request causes an Auth Req to MS
874 rx from MS: pdisc=0x05 msg_type=0x08
875 new conn
876DREF unknown: MSC conn use + 1 == 1
877DRLL Dispatching 04.08 message, pdisc=5
878DREF unknown: MSC conn use + 1 == 2
879DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
880DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
881DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
882DMM LOCATION UPDATING REQUEST: MI(TMSI)=50462976 type=IMSI ATTACH
883DMM LU/new-LAC: 1/0
884DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: Allocated
885DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: is child of Subscr_Conn(50462976)
886DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
887DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
888DREF VLR subscr MSISDN:46071 usage increases to: 2
889DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame^]890DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]891DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
892DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
893DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
894DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(50462976)
895DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
896DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
897DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=3
898- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=3 auth_types=0x1 and...
899- ...rand=fa8f20b781b5881329d4fea26b1a3c51
900- ...expecting sres=5afc8d72
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]901DMM compl_l3: Keeping conn
902DREF MSISDN:46071: MSC conn use - 1 == 1
903 auth_request_sent == 1
904 lu_result_sent == 0
905- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
906 rx from MS: pdisc=0x05 msg_type=0x54
907DREF MSISDN:46071: MSC conn use + 1 == 2
908DRLL Dispatching 04.08 message, pdisc=5
909DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 5afc8d72)
910DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
911DVLR SUBSCR(MSISDN:46071) received res: 5a fc 8d 72
912DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
913DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
914DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
915DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
916DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(50462976)
917DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
918DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
919DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
920DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
921DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
922DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
923DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
924DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: Allocated
925DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(50462976)
926DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
927DVLR GSUP tx: 04010809710000004026f0
928GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
929DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
930DREF MSISDN:46071: MSC conn use - 1 == 1
931 lu_result_sent == 0
932- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
933<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
934DVLR GSUP rx 17: 10010809710000004026f00804036470f1
935DREF VLR subscr MSISDN:46071 usage increases to: 3
936DVLR IMSI:901700000004620 has MSISDN:46071
937DVLR GSUP tx: 12010809710000004026f0
938GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
939DREF VLR subscr MSISDN:46071 usage decreases to: 2
940<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
941 lu_result_sent == 0
942- HLR also sends GSUP _UPDATE_LOCATION_RESULT
943<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
944DVLR GSUP rx 11: 06010809710000004026f0
945DREF VLR subscr MSISDN:46071 usage increases to: 3
946DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
947DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
948DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
949DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
950DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(50462976)
951DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Freeing instance
952DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Deallocated
953DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
954DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
955DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: Allocated
956DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(50462976)
957DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
958DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
959DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: Allocated
960DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(50462976)
961DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
962DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
963DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
964DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(50462976)
965DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Freeing instance
966DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Deallocated
967DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
968DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
969DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
970- sending LU Accept for MSISDN:46071, with TMSI 0x07060504
971DREF VLR subscr MSISDN:46071 usage decreases to: 2
972<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
973- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
974 llist_count(&net->subscr_conns) == 1
975 lu_result_sent == 1
976msc_subscr_conn_is_accepted() == false
977 requests shall be thwarted
978DRLL Dispatching 04.08 message, pdisc=3
979DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
980DRLL Dispatching 04.08 message, pdisc=5
981DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
982DRLL Dispatching 04.08 message, pdisc=6
983DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
984DRLL Dispatching 04.08 message, pdisc=9
985DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
986- even though the TMSI is not acked, we can already find the subscr with it
987DREF VLR subscr MSISDN:46071 usage increases to: 3
988 vsub != NULL == 1
989 strcmp(vsub->imsi, imsi) == 0
990 vsub->tmsi_new == 0x07060504
991 vsub->tmsi == 0x03020100
992DREF VLR subscr MSISDN:46071 usage decreases to: 2
993- MS sends TMSI Realloc Complete
994 rx from MS: pdisc=0x05 msg_type=0x5b
995DREF MSISDN:46071: MSC conn use + 1 == 2
996DRLL Dispatching 04.08 message, pdisc=5
997DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
998DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
999DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1000DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1001DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1002DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1003DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(50462976)
1004DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Freeing instance
1005DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Deallocated
1006DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1007DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1008DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1009DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1010DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1011DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1012DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1013DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1014DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(50462976)
1015DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1016DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Freeing instance
1017DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Deallocated
1018DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
1019DREF MSISDN:46071: MSC conn use - 1 == 1
1020DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
1021DVLR Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
1022DREF MSISDN:46071: MSC conn use - 1 == 0
1023DRLL subscr MSISDN:46071: Freeing subscriber connection
1024DREF VLR subscr MSISDN:46071 usage decreases to: 1
1025- LU was successful, and the conn has already been closed
1026 llist_count(&net->subscr_conns) == 0
1027- subscriber has the new TMSI
1028DREF VLR subscr MSISDN:46071 usage increases to: 2
1029 vsub != NULL == 1
1030 strcmp(vsub->imsi, imsi) == 0
1031 vsub->tmsi_new == 0xffffffff
1032 vsub->tmsi == 0x07060504
1033DREF VLR subscr MSISDN:46071 usage decreases to: 1
1034---
1035- subscriber detaches, using new TMSI
1036 rx from MS: pdisc=0x05 msg_type=0x01
1037 new conn
1038DREF unknown: MSC conn use + 1 == 1
1039DRLL Dispatching 04.08 message, pdisc=5
1040DMM IMSI DETACH INDICATION: MI(TMSI)=117835012
1041DREF VLR subscr MSISDN:46071 usage increases to: 2
1042DMM IMSI DETACH for MSISDN:46071
1043DREF VLR subscr MSISDN:46071 usage decreases to: 1
1044DREF VLR subscr MSISDN:46071 usage decreases to: 0
1045DREF freeing VLR subscr MSISDN:46071
1046DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
1047DMM No conn_fsm, release conn
1048DMM compl_l3: Discarding conn
1049DRLL Freeing subscriber connection with NULL subscriber
1050 llist_count(&net->subscr_conns) == 0
1051===== test_gsm_authen_tmsi: SUCCESS
1052
1053full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1054talloc_total_blocks(tall_bsc_ctx) == 75
1055
1056===== test_gsm_authen_imei
1057- Location Update request causes a GSUP Send Auth Info request to HLR
1058 rx from MS: pdisc=0x05 msg_type=0x08
1059 new conn
1060DREF unknown: MSC conn use + 1 == 1
1061DRLL Dispatching 04.08 message, pdisc=5
1062DREF unknown: MSC conn use + 1 == 2
1063DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1064DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1065DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1066DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
1067DMM LU/new-LAC: 1/0
1068DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1069DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1070DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
1071DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1072DREF VLR subscr unknown usage increases to: 1
1073DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1074DVLR New subscr, IMSI: 901700000004620
1075DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame^]1076DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1077DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1078DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1079DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1080DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1081DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1082DVLR GSUP tx: 08010809710000004026f0
1083GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1084DVLR VLR_Authenticate(901700000004620){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]1085DMM compl_l3: Keeping conn
1086DREF IMSI:901700000004620: MSC conn use - 1 == 1
1087 lu_result_sent == 0
1088- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1089<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1090DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1091DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1092DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1093DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1094DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
1095DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
1096- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1097- ...rand=585df1ae287f6e273dce07090d61320b
1098- ...expecting sres=2d8b2c3e
1099DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1100<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1101 auth_request_sent == 1
1102 lu_result_sent == 0
1103- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
1104<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1105DVLR GSUP rx 11: 06010809710000004026f0
1106DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1107DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
1108DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
1109DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1110<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1111msc_subscr_conn_is_accepted() == false
1112 requests shall be thwarted
1113DRLL Dispatching 04.08 message, pdisc=3
1114DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
1115DRLL Dispatching 04.08 message, pdisc=5
1116DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
1117DRLL Dispatching 04.08 message, pdisc=6
1118DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
1119DRLL Dispatching 04.08 message, pdisc=9
1120DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
1121 lu_result_sent == 0
1122- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
1123 rx from MS: pdisc=0x05 msg_type=0x54
1124DREF IMSI:901700000004620: MSC conn use + 1 == 2
1125DRLL Dispatching 04.08 message, pdisc=5
1126DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1127DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
1128DVLR SUBSCR(IMSI:901700000004620) received res: 2d 8b 2c 3e
1129DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1130DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1131DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1132DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1133DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1134DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1135DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1136DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1137DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1138DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1139DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1140DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1141DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1142DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1143DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1144DVLR GSUP tx: 04010809710000004026f0
1145GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1146DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1147DREF IMSI:901700000004620: MSC conn use - 1 == 1
1148 lu_result_sent == 0
1149- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1150<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1151DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1152DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1153DVLR IMSI:901700000004620 has MSISDN:46071
1154DVLR GSUP tx: 12010809710000004026f0
1155GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1156DREF VLR subscr MSISDN:46071 usage decreases to: 1
1157<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1158 lu_result_sent == 0
1159- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1160<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1161DVLR GSUP rx 11: 06010809710000004026f0
1162DREF VLR subscr MSISDN:46071 usage increases to: 2
1163DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1164DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1165DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1166DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1167DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1168DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1169DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1170DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1171DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1172DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1173DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1174DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1175DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1176DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1177DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1178DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1179DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1180DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1181DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1182DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1183DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1184DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1185DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_IMEI
1186- DTAP --> MS: 051802
1187- DTAP matches expected message
1188DREF VLR subscr MSISDN:46071 usage decreases to: 1
1189<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1190- We will only do business when the IMEI is known
1191 llist_count(&net->subscr_conns) == 1
1192DREF VLR subscr MSISDN:46071 usage increases to: 2
1193 vsub->imei[0] == 0
1194DREF VLR subscr MSISDN:46071 usage decreases to: 1
1195msc_subscr_conn_is_accepted() == false
1196 requests shall be thwarted
1197DRLL Dispatching 04.08 message, pdisc=3
1198DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
1199DRLL Dispatching 04.08 message, pdisc=5
1200DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
1201DRLL Dispatching 04.08 message, pdisc=6
1202DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
1203DRLL Dispatching 04.08 message, pdisc=9
1204DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
1205- MS replies with an Identity Response
1206 rx from MS: pdisc=0x05 msg_type=0x59
1207DREF MSISDN:46071: MSC conn use + 1 == 2
1208DRLL Dispatching 04.08 message, pdisc=5
1209DMM IDENTITY RESPONSE: MI(IMEI)=423423423423423
1210DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423423
1211DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1212DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1213- sending LU Accept for MSISDN:46071
1214DREF VLR subscr MSISDN:46071 usage increases to: 2
1215DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: state_chg to LU_COMPL_VLR_S_DONE
1216DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1217DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1218DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1219DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1220DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1221DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1222DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1223DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1224DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1225DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1226DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1227DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1228DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1229DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1230DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1231DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1232DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1233DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
1234DREF MSISDN:46071: MSC conn use - 1 == 1
1235DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1236DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
1237DREF MSISDN:46071: MSC conn use - 1 == 0
1238DRLL subscr MSISDN:46071: Freeing subscriber connection
1239DREF VLR subscr MSISDN:46071 usage decreases to: 1
1240- LU was successful, and the conn has already been closed
1241 lu_result_sent == 1
1242 llist_count(&net->subscr_conns) == 0
1243- Subscriber has the IMEI
1244DREF VLR subscr MSISDN:46071 usage increases to: 2
1245 strcmp(vsub->imei, "423423423423423") == 0
1246DREF VLR subscr MSISDN:46071 usage decreases to: 1
1247---
1248- subscriber detaches
1249 rx from MS: pdisc=0x05 msg_type=0x01
1250 new conn
1251DREF unknown: MSC conn use + 1 == 1
1252DRLL Dispatching 04.08 message, pdisc=5
1253DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1254DREF VLR subscr MSISDN:46071 usage increases to: 2
1255DMM IMSI DETACH for MSISDN:46071
1256DREF VLR subscr MSISDN:46071 usage decreases to: 1
1257DREF VLR subscr MSISDN:46071 usage decreases to: 0
1258DREF freeing VLR subscr MSISDN:46071
1259DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
1260DMM No conn_fsm, release conn
1261DMM compl_l3: Discarding conn
1262DRLL Freeing subscriber connection with NULL subscriber
1263 llist_count(&net->subscr_conns) == 0
1264===== test_gsm_authen_imei: SUCCESS
1265
1266full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1267talloc_total_blocks(tall_bsc_ctx) == 75
1268
1269===== test_gsm_authen_tmsi_imei
1270- Location Update request causes a GSUP Send Auth Info request to HLR
1271 rx from MS: pdisc=0x05 msg_type=0x08
1272 new conn
1273DREF unknown: MSC conn use + 1 == 1
1274DRLL Dispatching 04.08 message, pdisc=5
1275DREF unknown: MSC conn use + 1 == 2
1276DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1277DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1278DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1279DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
1280DMM LU/new-LAC: 1/0
1281DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1282DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1283DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
1284DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1285DREF VLR subscr unknown usage increases to: 1
1286DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1287DVLR New subscr, IMSI: 901700000004620
1288DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame^]1289DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1290DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1291DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1292DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1293DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1294DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1295DVLR GSUP tx: 08010809710000004026f0
1296GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1297DVLR VLR_Authenticate(901700000004620){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]1298DMM compl_l3: Keeping conn
1299DREF IMSI:901700000004620: MSC conn use - 1 == 1
1300 lu_result_sent == 0
1301- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1302<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1303DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1304DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1305DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1306DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1307DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
1308DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
1309- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1310- ...rand=585df1ae287f6e273dce07090d61320b
1311- ...expecting sres=2d8b2c3e
1312DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1313<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1314 auth_request_sent == 1
1315 lu_result_sent == 0
1316- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
1317<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1318DVLR GSUP rx 11: 06010809710000004026f0
1319DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1320DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
1321DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
1322DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1323<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1324msc_subscr_conn_is_accepted() == false
1325 requests shall be thwarted
1326DRLL Dispatching 04.08 message, pdisc=3
1327DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
1328DRLL Dispatching 04.08 message, pdisc=5
1329DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
1330DRLL Dispatching 04.08 message, pdisc=6
1331DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
1332DRLL Dispatching 04.08 message, pdisc=9
1333DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
1334 lu_result_sent == 0
1335- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
1336 rx from MS: pdisc=0x05 msg_type=0x54
1337DREF IMSI:901700000004620: MSC conn use + 1 == 2
1338DRLL Dispatching 04.08 message, pdisc=5
1339DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1340DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
1341DVLR SUBSCR(IMSI:901700000004620) received res: 2d 8b 2c 3e
1342DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1343DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1344DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1345DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1346DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1347DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1348DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1349DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1350DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1351DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1352DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1353DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1354DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1355DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1356DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1357DVLR GSUP tx: 04010809710000004026f0
1358GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1359DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1360DREF IMSI:901700000004620: MSC conn use - 1 == 1
1361 lu_result_sent == 0
1362- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1363<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1364DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1365DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1366DVLR IMSI:901700000004620 has MSISDN:46071
1367DVLR GSUP tx: 12010809710000004026f0
1368GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1369DREF VLR subscr MSISDN:46071 usage decreases to: 1
1370<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1371 lu_result_sent == 0
1372- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1373<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1374DVLR GSUP rx 11: 06010809710000004026f0
1375DREF VLR subscr MSISDN:46071 usage increases to: 2
1376DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1377DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1378DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1379DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1380DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1381DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1382DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1383DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1384DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1385DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1386DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1387DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1388DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1389DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1390DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1391DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1392DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1393DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1394DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1395DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1396DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1397DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1398DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_IMEI_TMSI
1399- DTAP --> MS: 051802
1400- DTAP matches expected message
1401DREF VLR subscr MSISDN:46071 usage decreases to: 1
1402<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1403- We will only do business when the IMEI is known
1404 llist_count(&net->subscr_conns) == 1
1405DREF VLR subscr MSISDN:46071 usage increases to: 2
1406 vsub->imei[0] == 0
1407DREF VLR subscr MSISDN:46071 usage decreases to: 1
1408msc_subscr_conn_is_accepted() == false
1409 requests shall be thwarted
1410DRLL Dispatching 04.08 message, pdisc=3
1411DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
1412DRLL Dispatching 04.08 message, pdisc=5
1413DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
1414DRLL Dispatching 04.08 message, pdisc=6
1415DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
1416DRLL Dispatching 04.08 message, pdisc=9
1417DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
1418- MS replies with an Identity Response
1419 rx from MS: pdisc=0x05 msg_type=0x59
1420DREF MSISDN:46071: MSC conn use + 1 == 2
1421DRLL Dispatching 04.08 message, pdisc=5
1422DMM IDENTITY RESPONSE: MI(IMEI)=423423423423423
1423DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423423
1424DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1425DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1426DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: lu_compl_vlr_new_tmsi()
1427DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1428- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
1429DREF MSISDN:46071: MSC conn use - 1 == 1
1430- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1431 llist_count(&net->subscr_conns) == 1
1432 lu_result_sent == 1
1433msc_subscr_conn_is_accepted() == false
1434 requests shall be thwarted
1435DRLL Dispatching 04.08 message, pdisc=3
1436DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
1437DRLL Dispatching 04.08 message, pdisc=5
1438DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
1439DRLL Dispatching 04.08 message, pdisc=6
1440DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
1441DRLL Dispatching 04.08 message, pdisc=9
1442DRLL subscr MSISDN:46071: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
1443- even though the TMSI is not acked, we can already find the subscr with it
1444DREF VLR subscr MSISDN:46071 usage increases to: 2
1445 vsub != NULL == 1
1446 strcmp(vsub->imsi, imsi) == 0
1447 vsub->tmsi_new == 0x03020100
1448 vsub->tmsi == 0xffffffff
1449DREF VLR subscr MSISDN:46071 usage decreases to: 1
1450- MS sends TMSI Realloc Complete
1451 rx from MS: pdisc=0x05 msg_type=0x5b
1452DREF MSISDN:46071: MSC conn use + 1 == 2
1453DRLL Dispatching 04.08 message, pdisc=5
1454DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
1455DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1456DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1457DREF VLR subscr MSISDN:46071 usage increases to: 2
1458DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1459DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1460DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1461DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1462DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1463DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1464DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1465DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1466DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1467DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1468DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1469DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1470DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1471DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1472DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1473DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1474DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1475DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1476DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
1477DREF MSISDN:46071: MSC conn use - 1 == 1
1478DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1479DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
1480DREF MSISDN:46071: MSC conn use - 1 == 0
1481DRLL subscr MSISDN:46071: Freeing subscriber connection
1482DREF VLR subscr MSISDN:46071 usage decreases to: 1
1483- LU was successful, and the conn has already been closed
1484 llist_count(&net->subscr_conns) == 0
1485- Subscriber has the IMEI and TMSI
1486DREF VLR subscr MSISDN:46071 usage increases to: 2
1487 strcmp(vsub->imei, "423423423423423") == 0
1488 vsub->tmsi == 0x03020100
1489DREF VLR subscr MSISDN:46071 usage decreases to: 1
1490---
1491- subscriber detaches, using TMSI
1492 rx from MS: pdisc=0x05 msg_type=0x01
1493 new conn
1494DREF unknown: MSC conn use + 1 == 1
1495DRLL Dispatching 04.08 message, pdisc=5
1496DMM IMSI DETACH INDICATION: MI(TMSI)=50462976
1497DREF VLR subscr MSISDN:46071 usage increases to: 2
1498DMM IMSI DETACH for MSISDN:46071
1499DREF VLR subscr MSISDN:46071 usage decreases to: 1
1500DREF VLR subscr MSISDN:46071 usage decreases to: 0
1501DREF freeing VLR subscr MSISDN:46071
1502DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
1503DMM No conn_fsm, release conn
1504DMM compl_l3: Discarding conn
1505DRLL Freeing subscriber connection with NULL subscriber
1506 llist_count(&net->subscr_conns) == 0
1507===== test_gsm_authen_tmsi_imei: SUCCESS
1508
1509full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1510talloc_total_blocks(tall_bsc_ctx) == 75
1511
1512===== test_gsm_milenage_authen
1513- Location Update request causes a GSUP Send Auth Info request to HLR
1514 rx from MS: pdisc=0x05 msg_type=0x08
1515 new conn
1516DREF unknown: MSC conn use + 1 == 1
1517DRLL Dispatching 04.08 message, pdisc=5
1518DREF unknown: MSC conn use + 1 == 2
1519DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1520DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1521DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1522DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1523DMM LU/new-LAC: 0/0
1524DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1525DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1526DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
1527DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1528DREF VLR subscr unknown usage increases to: 1
1529DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1530DVLR New subscr, IMSI: 901700000010650
1531DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame^]1532DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1533DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1534DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1535DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1536DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1537DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1538DVLR GSUP tx: 08010809710000000156f0
1539GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1540DVLR 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]1541DMM compl_l3: Keeping conn
1542DREF IMSI:901700000010650: MSC conn use - 1 == 1
1543 lu_result_sent == 0
1544- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1545<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c
1546DVLR GSUP rx 311: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c
1547DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1548DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1549DVLR SUBSCR(IMSI:901700000010650) Received 3 auth tuples
1550DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
1551DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
1552- sending GSM Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1553- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1554- ...expecting sres=9b36efdf
1555DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1556<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1557 auth_request_sent == 1
1558 lu_result_sent == 0
1559- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
1560 rx from MS: pdisc=0x05 msg_type=0x54
1561DREF IMSI:901700000010650: MSC conn use + 1 == 2
1562DRLL Dispatching 04.08 message, pdisc=5
1563DMM IMSI:901700000010650: MM GSM AUTHENTICATION RESPONSE (sres = 9b36efdf)
1564DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
1565DVLR SUBSCR(IMSI:901700000010650) received res: 9b 36 ef df
1566DVLR SUBSCR(IMSI:901700000010650) AUTH established GSM security context
1567DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1568DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1569DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1570DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
1571DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1572DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1573DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1574DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1575DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1576DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1577DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1578DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1579DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1580DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1581DVLR GSUP tx: 04010809710000000156f0
1582GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
1583DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1584DREF IMSI:901700000010650: MSC conn use - 1 == 1
1585 lu_result_sent == 0
1586- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1587<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1588DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1589DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1590DVLR IMSI:901700000010650 has MSISDN:42342
1591DVLR GSUP tx: 12010809710000000156f0
1592GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1593DREF VLR subscr MSISDN:42342 usage decreases to: 1
1594<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1595 lu_result_sent == 0
1596- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1597<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1598DVLR GSUP rx 11: 06010809710000000156f0
1599DREF VLR subscr MSISDN:42342 usage increases to: 2
1600DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1601DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1602DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1603DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1604DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1605DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1606DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1607DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1608DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1609DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1610DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1611DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1612DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1613DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1614DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
1615DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1616DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1617DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1618DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
1619DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1620DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1621DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1622- sending LU Accept for MSISDN:42342
1623DREF VLR subscr MSISDN:42342 usage increases to: 3
1624DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1625DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1626DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1627DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1628DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1629DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1630DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1631DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1632DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1633DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1634DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1635DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1636DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1637DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1638DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1639DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1640DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1641DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1642DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
1643DREF MSISDN:42342: MSC conn use - 1 == 0
1644DRLL subscr MSISDN:42342: Freeing subscriber connection
1645DREF VLR subscr MSISDN:42342 usage decreases to: 2
1646DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1647DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1648DREF VLR subscr MSISDN:42342 usage decreases to: 1
1649<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1650- LU was successful, and the conn has already been closed
1651 lu_result_sent == 1
1652 llist_count(&net->subscr_conns) == 0
1653---
1654- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
1655 rx from MS: pdisc=0x05 msg_type=0x24
1656 new conn
1657DREF unknown: MSC conn use + 1 == 1
1658DRLL Dispatching 04.08 message, pdisc=5
1659DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
1660DREF unknown: MSC conn use + 1 == 2
1661DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1662DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1663DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1664DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
1665DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
1666DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
1667DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1668DREF VLR subscr MSISDN:42342 usage increases to: 2
1669DREF VLR subscr MSISDN:42342 usage increases to: 3
1670DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1671DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1672DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1673DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
1674DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1675DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
1676DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
1677- sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
1678- ...rand=c187a53a5e6b9d573cac7c74451fd46d
1679- ...expecting sres=85aa3130
1680DREF VLR subscr MSISDN:42342 usage decreases to: 2
1681DMM compl_l3: Keeping conn
1682DREF MSISDN:42342: MSC conn use - 1 == 1
1683 cm_service_result_sent == 0
1684 auth_request_sent == 1
1685- needs auth, not yet accepted
1686msc_subscr_conn_is_accepted() == false
1687 requests shall be thwarted
1688DRLL Dispatching 04.08 message, pdisc=3
1689DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
1690DRLL Dispatching 04.08 message, pdisc=5
1691DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
1692DRLL Dispatching 04.08 message, pdisc=6
1693DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
1694DRLL Dispatching 04.08 message, pdisc=9
1695DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
1696- MS sends Authen Response, VLR accepts with a CM Service Accept
1697 rx from MS: pdisc=0x05 msg_type=0x54
1698DREF MSISDN:42342: MSC conn use + 1 == 2
1699DRLL Dispatching 04.08 message, pdisc=5
1700DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 85aa3130)
1701DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
1702DVLR SUBSCR(MSISDN:42342) received res: 85 aa 31 30
1703DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
1704DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1705DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1706DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1707DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
1708DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1709DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1710DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
1711DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
1712DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1713DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
1714DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
1715DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
1716DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
1717DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
1718DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1719DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
1720DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1721- sending CM Service Accept for MSISDN:42342
1722DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1723DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
1724DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1725DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
1726DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1727DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1728DREF MSISDN:42342: MSC conn use - 1 == 1
1729 cm_service_result_sent == 1
1730- a USSD request is serviced
1731 expecting USSD:
1732 Your extension is 42342
1733 rx from MS: pdisc=0x0b msg_type=0x3b
1734DREF MSISDN:42342: MSC conn use + 1 == 2
1735DRLL Dispatching 04.08 message, pdisc=11
1736DMM MSISDN:42342 pdisc=11 msg_type=0x3b: received_cm_service_request changes to false
1737DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1738DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
1739DMM USSD: Own number requested
1740DMM MSISDN:42342: MSISDN = 42342
1741- DTAP --> MS: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
1742- DTAP matches expected message
1743DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
1744DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1745DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1746DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1747DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1748DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
1749DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
1750DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
1751DREF MSISDN:42342: MSC conn use - 1 == 1
1752DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1753DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1754DREF MSISDN:42342: MSC conn use - 1 == 0
1755DRLL subscr MSISDN:42342: Freeing subscriber connection
1756DREF VLR subscr MSISDN:42342 usage decreases to: 1
1757- all requests serviced, conn has been released
1758 llist_count(&net->subscr_conns) == 0
1759---
1760- an SMS is sent, MS is paged
1761DREF VLR subscr MSISDN:42342 usage increases to: 2
1762 llist_count(&vsub->cs.requests) == 0
1763DREF VLR subscr MSISDN:42342 usage increases to: 3
1764DMM Subscriber MSISDN:42342 not paged yet.
1765 BTS/BSC sends out paging request to IMSI:901700000010650 for channel type 1
1766 strcmp(paging_expecting_imsi, sub->imsi) == 0
1767DREF BSC subscr IMSI:901700000010650 usage decreases to: 0
1768DREF VLR subscr MSISDN:42342 usage increases to: 4
1769 llist_count(&vsub->cs.requests) == 1
1770DREF VLR subscr MSISDN:42342 usage decreases to: 3
1771 paging_sent == 1
1772 paging_stopped == 0
1773- the subscriber and its pending request should remain
1774DREF VLR subscr MSISDN:42342 usage increases to: 4
1775 llist_count(&vsub->cs.requests) == 1
1776DREF VLR subscr MSISDN:42342 usage decreases to: 3
1777- MS replies with Paging Response, and VLR sends Auth Request with third key
1778 rx from MS: pdisc=0x06 msg_type=0x27
1779 new conn
1780DREF unknown: MSC conn use + 1 == 1
1781DRLL Dispatching 04.08 message, pdisc=6
1782DRR PAGING RESPONSE: MI(IMSI)=901700000010650
1783DREF unknown: MSC conn use + 1 == 2
1784DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1785DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1786DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1787DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
1788DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
1789DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
1790DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1791DREF VLR subscr MSISDN:42342 usage increases to: 4
1792DREF VLR subscr MSISDN:42342 usage increases to: 5
1793DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1794DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1795DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1796DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
1797DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1798DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
1799DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2
1800- sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
1801- ...rand=efa9c29a9742148d5c9070348716e1bb
1802- ...expecting sres=69d5f9fb
1803DREF VLR subscr MSISDN:42342 usage decreases to: 4
1804DMM compl_l3: Keeping conn
1805DREF MSISDN:42342: MSC conn use - 1 == 1
1806 auth_request_sent == 1
1807- needs auth, not yet accepted
1808msc_subscr_conn_is_accepted() == false
1809 requests shall be thwarted
1810DRLL Dispatching 04.08 message, pdisc=3
1811DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
1812DRLL Dispatching 04.08 message, pdisc=5
1813DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
1814DRLL Dispatching 04.08 message, pdisc=6
1815DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
1816DRLL Dispatching 04.08 message, pdisc=9
1817DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
1818- MS sends Authen Response, VLR accepts and sends pending SMS
1819 rx from MS: pdisc=0x05 msg_type=0x54
1820DREF MSISDN:42342: MSC conn use + 1 == 2
1821DRLL Dispatching 04.08 message, pdisc=5
1822DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 69d5f9fb)
1823DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
1824DVLR SUBSCR(MSISDN:42342) received res: 69 d5 f9 fb
1825DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
1826DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1827DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1828DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1829DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
1830DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1831DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1832DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
1833DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
1834DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1835DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
1836DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
1837DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
1838DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
1839DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
1840DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1841DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
1842DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1843DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1844DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
1845DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1846DREF BSC subscr IMSI:901700000010650 usage decreases to: 0
1847DREF VLR subscr MSISDN:42342 usage increases to: 5
1848DREF MSISDN:42342: MSC conn use + 1 == 3
1849- DTAP --> MS: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
1850- DTAP matches expected message
1851DREF VLR subscr MSISDN:42342 usage decreases to: 4
1852DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1853DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1854DREF MSISDN:42342: MSC conn use - 1 == 2
1855 dtap_tx_confirmed == 1
1856 paging_stopped == 1
1857- SMS was delivered, no requests pending for subscr
1858DREF VLR subscr MSISDN:42342 usage increases to: 5
1859 llist_count(&vsub->cs.requests) == 0
1860DREF VLR subscr MSISDN:42342 usage decreases to: 4
1861- conn is still open to wait for SMS ack dance
1862 llist_count(&net->subscr_conns) == 1
1863- MS replies with CP-ACK for received SMS
1864 rx from MS: pdisc=0x89 msg_type=0x04
1865DREF MSISDN:42342: MSC conn use + 1 == 3
1866DRLL Dispatching 04.08 message, pdisc=9
1867DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1868DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
1869DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
1870DREF MSISDN:42342: MSC conn use - 1 == 2
1871 llist_count(&net->subscr_conns) == 1
1872- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
1873 rx from MS: pdisc=0x89 msg_type=0x01
1874DREF MSISDN:42342: MSC conn use + 1 == 3
1875DRLL Dispatching 04.08 message, pdisc=9
1876DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
1877- DTAP --> MS: 0904
1878- DTAP matches expected message
1879DREF VLR subscr MSISDN:42342 usage decreases to: 3
1880DREF VLR subscr MSISDN:42342 usage decreases to: 2
1881DREF MSISDN:42342: MSC conn use - 1 == 2
1882DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
1883DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1884DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1885DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1886DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1887DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
1888DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
1889DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
1890DREF MSISDN:42342: MSC conn use - 1 == 1
1891DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1892DVLR Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1893DREF MSISDN:42342: MSC conn use - 1 == 0
1894DRLL subscr MSISDN:42342: Freeing subscriber connection
1895DREF VLR subscr MSISDN:42342 usage decreases to: 1
1896 dtap_tx_confirmed == 1
1897- SMS is done, conn is gone
1898 llist_count(&net->subscr_conns) == 0
1899---
1900- subscriber detaches
1901 rx from MS: pdisc=0x05 msg_type=0x01
1902 new conn
1903DREF unknown: MSC conn use + 1 == 1
1904DRLL Dispatching 04.08 message, pdisc=5
1905DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
1906DREF VLR subscr MSISDN:42342 usage increases to: 2
1907DMM IMSI DETACH for MSISDN:42342
1908DREF VLR subscr MSISDN:42342 usage decreases to: 1
1909DREF VLR subscr MSISDN:42342 usage decreases to: 0
1910DREF freeing VLR subscr MSISDN:42342
1911DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
1912DMM No conn_fsm, release conn
1913DMM compl_l3: Discarding conn
1914DRLL Freeing subscriber connection with NULL subscriber
1915 llist_count(&net->subscr_conns) == 0
1916===== test_gsm_milenage_authen: SUCCESS
1917
1918full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1919talloc_total_blocks(tall_bsc_ctx) == 75
1920
1921full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1922talloc_total_blocks(tall_bsc_ctx) == 9
1923