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