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