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