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