Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-gbproxy / 5dd2508c73ec956ea33447c4389b7a63bc89f255 / . / tests / msc_vlr / msc_vlr_test_reject_concurrency.err
blob: bebb16b2c2ea320430e778ae05d8d60e3ff68eab [file] [log] [blame]
Neels Hofmeyr3dc2c642017-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 Hofmeyr0e255582017-07-18 15:39:27 +0200[diff] [blame]21DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr3dc2c642017-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 Hofmeyr3dc2c642017-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 Hofmeyr0e255582017-07-18 15:39:27 +0200[diff] [blame]171DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr3dc2c642017-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 Hofmeyr3dc2c642017-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 Hofmeyr0e255582017-07-18 15:39:27 +0200[diff] [blame]291DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr3dc2c642017-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 Hofmeyr3dc2c642017-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 Hofmeyr0e255582017-07-18 15:39:27 +0200[diff] [blame]416DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr3dc2c642017-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 Hofmeyr3dc2c642017-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 Hofmeyr0e255582017-07-18 15:39:27 +0200[diff] [blame]539DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr3dc2c642017-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 Hofmeyr3dc2c642017-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 Hofmeyr0e255582017-07-18 15:39:27 +0200[diff] [blame]724DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr3dc2c642017-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 Hofmeyr3dc2c642017-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 Hofmeyr0e255582017-07-18 15:39:27 +0200[diff] [blame]911DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr3dc2c642017-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 Hofmeyr3dc2c642017-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 Hofmeyr0e255582017-07-18 15:39:27 +0200[diff] [blame]1102DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr3dc2c642017-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 Hofmeyr3dc2c642017-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.
Neels Hofmeyr5dd25082017-05-08 15:12:20 +0200[diff] [blame^]1191 BTS/BSC sends out paging request to MSISDN:46071
1192 strcmp(paging_expecting_imsi, vsub->imsi) == 0
Neels Hofmeyr3dc2c642017-01-25 15:04:16 +0100[diff] [blame]1193DREF VLR subscr MSISDN:46071 usage increases to: 4
1194 llist_count(&vsub->cs.requests) == 1
1195DREF VLR subscr MSISDN:46071 usage decreases to: 3
1196 paging_sent == 1
1197 paging_stopped == 0
1198- MS replies with Paging Response, we deliver the SMS
1199 rx from MS: pdisc=0x06 msg_type=0x27
1200 new conn
1201DREF unknown: MSC conn use + 1 == 1
1202DRLL Dispatching 04.08 message, pdisc=6
1203DRR PAGING RESPONSE: MI(IMSI)=901700000004620
1204DREF unknown: MSC conn use + 1 == 2
1205DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1206DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1207DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1208DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
1209DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
1210DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1211DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1212DREF VLR subscr MSISDN:46071 usage increases to: 4
1213DREF VLR subscr MSISDN:46071 usage increases to: 5
1214DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1215DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1216DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1217DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1218DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1219DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1220DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
1221DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1222DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
1223DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1224DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1225DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
1226DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyr3dc2c642017-01-25 15:04:16 +0100[diff] [blame]1227DREF VLR subscr MSISDN:46071 usage increases to: 6
1228DREF MSISDN:46071: MSC conn use + 1 == 3
1229- DTAP --> MS: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
1230- DTAP matches expected message
1231DREF VLR subscr MSISDN:46071 usage decreases to: 5
1232DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1233DREF VLR subscr MSISDN:46071 usage decreases to: 4
1234DMM compl_l3: Keeping conn
1235DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1236DREF MSISDN:46071: MSC conn use - 1 == 2
1237 dtap_tx_confirmed == 1
1238 paging_stopped == 1
1239- conn is still open to wait for SMS ack dance
1240 llist_count(&net->subscr_conns) == 1
1241---
1242- MS sends erratic LU Request, which is dropped silently
1243 rx from MS: pdisc=0x05 msg_type=0x08
1244DREF MSISDN:46071: MSC conn use + 1 == 3
1245DRLL Dispatching 04.08 message, pdisc=5
1246DMM 901700000004620: Error: connection already in use
1247DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1248DREF MSISDN:46071: MSC conn use - 1 == 2
1249 lu_result_sent == 0
1250 llist_count(&net->subscr_conns) == 1
1251- MS replies with CP-ACK for received SMS
1252 rx from MS: pdisc=0x89 msg_type=0x04
1253DREF MSISDN:46071: MSC conn use + 1 == 3
1254DRLL Dispatching 04.08 message, pdisc=9
1255DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1256DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
1257DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
1258DREF MSISDN:46071: MSC conn use - 1 == 2
1259 llist_count(&net->subscr_conns) == 1
1260- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
1261 rx from MS: pdisc=0x89 msg_type=0x01
1262DREF MSISDN:46071: MSC conn use + 1 == 3
1263DRLL Dispatching 04.08 message, pdisc=9
1264DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
1265- DTAP --> MS: 0904
1266- DTAP matches expected message
1267DREF VLR subscr MSISDN:46071 usage decreases to: 3
1268DREF VLR subscr MSISDN:46071 usage decreases to: 2
1269DREF MSISDN:46071: MSC conn use - 1 == 2
1270DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
1271DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1272DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1273DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1274DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1275DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
1276DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
1277DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
1278DREF MSISDN:46071: MSC conn use - 1 == 1
1279DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1280DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
1281DREF MSISDN:46071: MSC conn use - 1 == 0
1282DRLL subscr MSISDN:46071: Freeing subscriber connection
1283DREF VLR subscr MSISDN:46071 usage decreases to: 1
1284 dtap_tx_confirmed == 1
1285- SMS is done
1286 llist_count(&net->subscr_conns) == 0
1287DREF freeing VLR subscr MSISDN:46071
1288===== test_reject_lu_during_paging_resp: SUCCESS
1289
1290full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1291talloc_total_blocks(tall_bsc_ctx) == 75
1292
1293===== test_reject_cm_during_paging_resp
1294---
1295- Subscriber does a normal LU
1296- Location Update Request
1297 rx from MS: pdisc=0x05 msg_type=0x08
1298 new conn
1299DREF unknown: MSC conn use + 1 == 1
1300DRLL Dispatching 04.08 message, pdisc=5
1301DREF unknown: MSC conn use + 1 == 2
1302DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1303DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1304DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1305DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
1306DMM LU/new-LAC: 1/0
1307DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1308DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1309DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1310DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1311DREF VLR subscr unknown usage increases to: 1
1312DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1313DVLR New subscr, IMSI: 901700000004620
1314DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr0e255582017-07-18 15:39:27 +0200[diff] [blame]1315DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr3dc2c642017-01-25 15:04:16 +0100[diff] [blame]1316DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1317DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1318DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1319DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1320DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1321DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1322DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1323DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1324DVLR GSUP tx: 04010809710000004026f0
1325GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1326DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyr3dc2c642017-01-25 15:04:16 +0100[diff] [blame]1327DMM compl_l3: Keeping conn
1328DREF IMSI:901700000004620: MSC conn use - 1 == 1
1329 lu_result_sent == 0
1330 llist_count(&net->subscr_conns) == 1
1331- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1332<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1333DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1334DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1335DVLR IMSI:901700000004620 has MSISDN:46071
1336DVLR GSUP tx: 12010809710000004026f0
1337GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1338DREF VLR subscr MSISDN:46071 usage decreases to: 1
1339<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1340 lu_result_sent == 0
1341- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1342<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1343DVLR GSUP rx 11: 06010809710000004026f0
1344DREF VLR subscr MSISDN:46071 usage increases to: 2
1345DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1346DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1347DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1348DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1349DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1350DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1351DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1352DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1353DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1354DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1355DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1356DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1357DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1358DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1359DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1360DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1361DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1362DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1363DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1364DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1365DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1366DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1367- sending LU Accept for MSISDN:46071
1368DREF VLR subscr MSISDN:46071 usage increases to: 3
1369DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1370DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1371DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1372DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1373DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1374DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1375DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1376DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1377DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1378DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1379DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1380DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1381DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1382DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1383DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1384DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1385DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1386DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1387DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
1388DREF MSISDN:46071: MSC conn use - 1 == 0
1389DRLL subscr MSISDN:46071: Freeing subscriber connection
1390DREF VLR subscr MSISDN:46071 usage decreases to: 2
1391DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1392DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
1393DREF VLR subscr MSISDN:46071 usage decreases to: 1
1394<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1395- LU was successful, and the conn has already been closed
1396 lu_result_sent == 1
1397 llist_count(&net->subscr_conns) == 0
1398---
1399- an SMS is sent, MS is paged
1400DREF VLR subscr MSISDN:46071 usage increases to: 2
1401 llist_count(&vsub->cs.requests) == 0
1402DREF VLR subscr MSISDN:46071 usage increases to: 3
1403DMM Subscriber MSISDN:46071 not paged yet.
Neels Hofmeyr5dd25082017-05-08 15:12:20 +0200[diff] [blame^]1404 BTS/BSC sends out paging request to MSISDN:46071
1405 strcmp(paging_expecting_imsi, vsub->imsi) == 0
Neels Hofmeyr3dc2c642017-01-25 15:04:16 +0100[diff] [blame]1406DREF VLR subscr MSISDN:46071 usage increases to: 4
1407 llist_count(&vsub->cs.requests) == 1
1408DREF VLR subscr MSISDN:46071 usage decreases to: 3
1409 paging_sent == 1
1410 paging_stopped == 0
1411- MS replies with Paging Response, we deliver the SMS
1412 rx from MS: pdisc=0x06 msg_type=0x27
1413 new conn
1414DREF unknown: MSC conn use + 1 == 1
1415DRLL Dispatching 04.08 message, pdisc=6
1416DRR PAGING RESPONSE: MI(IMSI)=901700000004620
1417DREF unknown: MSC conn use + 1 == 2
1418DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1419DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1420DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1421DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
1422DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
1423DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1424DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1425DREF VLR subscr MSISDN:46071 usage increases to: 4
1426DREF VLR subscr MSISDN:46071 usage increases to: 5
1427DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1428DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1429DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1430DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1431DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1432DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1433DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
1434DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1435DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
1436DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1437DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1438DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
1439DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyr3dc2c642017-01-25 15:04:16 +0100[diff] [blame]1440DREF VLR subscr MSISDN:46071 usage increases to: 6
1441DREF MSISDN:46071: MSC conn use + 1 == 3
1442- DTAP --> MS: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
1443- DTAP matches expected message
1444DREF VLR subscr MSISDN:46071 usage decreases to: 5
1445DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1446DREF VLR subscr MSISDN:46071 usage decreases to: 4
1447DMM compl_l3: Keeping conn
1448DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1449DREF MSISDN:46071: MSC conn use - 1 == 2
1450 dtap_tx_confirmed == 1
1451 paging_stopped == 1
1452- conn is still open to wait for SMS ack dance
1453 llist_count(&net->subscr_conns) == 1
1454---
1455- CM Service Request during open connection is accepted
1456 rx from MS: pdisc=0x05 msg_type=0x24
1457DREF MSISDN:46071: MSC conn use + 1 == 3
1458DRLL Dispatching 04.08 message, pdisc=5
1459DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
1460DMM MSISDN:46071: re-using already accepted connection
1461- sending CM Service Accept for MSISDN:46071
1462DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1463DREF MSISDN:46071: MSC conn use - 1 == 2
1464 cm_service_result_sent == 1
1465 llist_count(&net->subscr_conns) == 1
1466 g_conn->received_cm_service_request == 1
1467- MS replies with CP-ACK for received SMS
1468 rx from MS: pdisc=0x89 msg_type=0x04
1469DREF MSISDN:46071: MSC conn use + 1 == 3
1470DRLL Dispatching 04.08 message, pdisc=9
1471DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1472DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
1473DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
1474DREF MSISDN:46071: MSC conn use - 1 == 2
1475 llist_count(&net->subscr_conns) == 1
1476- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
1477 rx from MS: pdisc=0x89 msg_type=0x01
1478DREF MSISDN:46071: MSC conn use + 1 == 3
1479DRLL Dispatching 04.08 message, pdisc=9
1480DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
1481- DTAP --> MS: 0904
1482- DTAP matches expected message
1483DREF VLR subscr MSISDN:46071 usage decreases to: 3
1484DREF VLR subscr MSISDN:46071 usage decreases to: 2
1485DREF MSISDN:46071: MSC conn use - 1 == 2
1486DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
1487DREF MSISDN:46071: MSC conn use - 1 == 1
1488 dtap_tx_confirmed == 1
1489- SMS is done
1490 llist_count(&net->subscr_conns) == 1
1491---
1492- subscriber detaches
1493 rx from MS: pdisc=0x05 msg_type=0x01
1494DREF MSISDN:46071: MSC conn use + 1 == 2
1495DRLL Dispatching 04.08 message, pdisc=5
1496DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1497DREF VLR subscr MSISDN:46071 usage increases to: 3
1498DMM IMSI DETACH for MSISDN:46071
1499DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_ERROR)
1500DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1501DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
1502DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
1503DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_CN_CLOSE
1504DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1505DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1506DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
1507DREF MSISDN:46071: MSC conn use - 1 == 1
1508DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1509DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
1510DREF VLR subscr MSISDN:46071 usage decreases to: 2
1511DREF VLR subscr MSISDN:46071 usage decreases to: 1
1512DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=0): already dispatching release, ignore.
1513DREF MSISDN:46071: MSC conn use - 1 == 0
1514DRLL subscr MSISDN:46071: Freeing subscriber connection
1515DREF VLR subscr MSISDN:46071 usage decreases to: 0
1516DREF freeing VLR subscr MSISDN:46071
1517 llist_count(&net->subscr_conns) == 0
1518===== test_reject_cm_during_paging_resp: SUCCESS
1519
1520full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1521talloc_total_blocks(tall_bsc_ctx) == 75
1522
1523===== test_reject_paging_resp_during_paging_resp
1524---
1525- Subscriber does a normal LU
1526- Location Update Request
1527 rx from MS: pdisc=0x05 msg_type=0x08
1528 new conn
1529DREF unknown: MSC conn use + 1 == 1
1530DRLL Dispatching 04.08 message, pdisc=5
1531DREF unknown: MSC conn use + 1 == 2
1532DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1533DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1534DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1535DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
1536DMM LU/new-LAC: 1/0
1537DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1538DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1539DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
1540DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1541DREF VLR subscr unknown usage increases to: 1
1542DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1543DVLR New subscr, IMSI: 901700000004620
1544DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr0e255582017-07-18 15:39:27 +0200[diff] [blame]1545DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr3dc2c642017-01-25 15:04:16 +0100[diff] [blame]1546DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1547DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
1548DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
1549DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
1550DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1551DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1552DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1553DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1554DVLR GSUP tx: 04010809710000004026f0
1555GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1556DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyr3dc2c642017-01-25 15:04:16 +0100[diff] [blame]1557DMM compl_l3: Keeping conn
1558DREF IMSI:901700000004620: MSC conn use - 1 == 1
1559 lu_result_sent == 0
1560 llist_count(&net->subscr_conns) == 1
1561- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1562<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1563DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1564DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1565DVLR IMSI:901700000004620 has MSISDN:46071
1566DVLR GSUP tx: 12010809710000004026f0
1567GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1568DREF VLR subscr MSISDN:46071 usage decreases to: 1
1569<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1570 lu_result_sent == 0
1571- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1572<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1573DVLR GSUP rx 11: 06010809710000004026f0
1574DREF VLR subscr MSISDN:46071 usage increases to: 2
1575DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1576DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1577DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1578DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1579DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1580DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1581DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1582DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1583DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1584DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1585DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1586DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1587DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1588DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1589DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1590DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1591DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1592DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1593DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1594DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1595DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1596DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1597- sending LU Accept for MSISDN:46071
1598DREF VLR subscr MSISDN:46071 usage increases to: 3
1599DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1600DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1601DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1602DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1603DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1604DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1605DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1606DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1607DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1608DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1609DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1610DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1611DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1612DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1613DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1614DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1615DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1616DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1617DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
1618DREF MSISDN:46071: MSC conn use - 1 == 0
1619DRLL subscr MSISDN:46071: Freeing subscriber connection
1620DREF VLR subscr MSISDN:46071 usage decreases to: 2
1621DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1622DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
1623DREF VLR subscr MSISDN:46071 usage decreases to: 1
1624<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1625- LU was successful, and the conn has already been closed
1626 lu_result_sent == 1
1627 llist_count(&net->subscr_conns) == 0
1628---
1629- an SMS is sent, MS is paged
1630DREF VLR subscr MSISDN:46071 usage increases to: 2
1631 llist_count(&vsub->cs.requests) == 0
1632DREF VLR subscr MSISDN:46071 usage increases to: 3
1633DMM Subscriber MSISDN:46071 not paged yet.
Neels Hofmeyr5dd25082017-05-08 15:12:20 +0200[diff] [blame^]1634 BTS/BSC sends out paging request to MSISDN:46071
1635 strcmp(paging_expecting_imsi, vsub->imsi) == 0
Neels Hofmeyr3dc2c642017-01-25 15:04:16 +0100[diff] [blame]1636DREF VLR subscr MSISDN:46071 usage increases to: 4
1637 llist_count(&vsub->cs.requests) == 1
1638DREF VLR subscr MSISDN:46071 usage decreases to: 3
1639 paging_sent == 1
1640 paging_stopped == 0
1641- MS replies with Paging Response, we deliver the SMS
1642 rx from MS: pdisc=0x06 msg_type=0x27
1643 new conn
1644DREF unknown: MSC conn use + 1 == 1
1645DRLL Dispatching 04.08 message, pdisc=6
1646DRR PAGING RESPONSE: MI(IMSI)=901700000004620
1647DREF unknown: MSC conn use + 1 == 2
1648DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1649DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1650DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1651DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
1652DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
1653DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
1654DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1655DREF VLR subscr MSISDN:46071 usage increases to: 4
1656DREF VLR subscr MSISDN:46071 usage increases to: 5
1657DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1658DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
1659DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
1660DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
1661DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
1662DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
1663DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
1664DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1665DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
1666DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1667DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1668DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
1669DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyr3dc2c642017-01-25 15:04:16 +0100[diff] [blame]1670DREF VLR subscr MSISDN:46071 usage increases to: 6
1671DREF MSISDN:46071: MSC conn use + 1 == 3
1672- DTAP --> MS: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
1673- DTAP matches expected message
1674DREF VLR subscr MSISDN:46071 usage decreases to: 5
1675DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1676DREF VLR subscr MSISDN:46071 usage decreases to: 4
1677DMM compl_l3: Keeping conn
1678DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1679DREF MSISDN:46071: MSC conn use - 1 == 2
1680 dtap_tx_confirmed == 1
1681 paging_stopped == 1
1682- conn is still open to wait for SMS ack dance
1683 llist_count(&net->subscr_conns) == 1
1684---
1685- MS sends another erratic Paging Response which is dropped silently
1686 rx from MS: pdisc=0x06 msg_type=0x27
1687DREF MSISDN:46071: MSC conn use + 1 == 3
1688DRLL Dispatching 04.08 message, pdisc=6
1689DRR PAGING RESPONSE: MI(IMSI)=901700000004620
1690DMM 901700000004620: Error: connection already in use
1691DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1692DREF MSISDN:46071: MSC conn use - 1 == 2
1693- MS replies with CP-ACK for received SMS
1694 rx from MS: pdisc=0x89 msg_type=0x04
1695DREF MSISDN:46071: MSC conn use + 1 == 3
1696DRLL Dispatching 04.08 message, pdisc=9
1697DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1698DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
1699DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
1700DREF MSISDN:46071: MSC conn use - 1 == 2
1701 llist_count(&net->subscr_conns) == 1
1702- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
1703 rx from MS: pdisc=0x89 msg_type=0x01
1704DREF MSISDN:46071: MSC conn use + 1 == 3
1705DRLL Dispatching 04.08 message, pdisc=9
1706DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
1707- DTAP --> MS: 0904
1708- DTAP matches expected message
1709DREF VLR subscr MSISDN:46071 usage decreases to: 3
1710DREF VLR subscr MSISDN:46071 usage decreases to: 2
1711DREF MSISDN:46071: MSC conn use - 1 == 2
1712DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
1713DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1714DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1715DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1716DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1717DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
1718DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
1719DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
1720DREF MSISDN:46071: MSC conn use - 1 == 1
1721DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1722DVLR Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
1723DREF MSISDN:46071: MSC conn use - 1 == 0
1724DRLL subscr MSISDN:46071: Freeing subscriber connection
1725DREF VLR subscr MSISDN:46071 usage decreases to: 1
1726 dtap_tx_confirmed == 1
1727- SMS is done
1728 llist_count(&net->subscr_conns) == 0
1729DREF freeing VLR subscr MSISDN:46071
1730===== test_reject_paging_resp_during_paging_resp: SUCCESS
1731
1732full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1733talloc_total_blocks(tall_bsc_ctx) == 75
1734
1735full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1736talloc_total_blocks(tall_bsc_ctx) == 9
1737