aboutsummaryrefslogtreecommitdiffstats
path: root/tests/msc_vlr/msc_vlr_test_hlr_timeout.err
blob: 68368c079dbaf6d8e5f4668d5238e38cbe28a697 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
DLMGCP MGCP client: using endpoint domain '@mgw'
full talloc report on 'msgb' (total      0 bytes in   1 blocks)
talloc_total_blocks(tall_bsc_ctx) == 19

===== test_hlr_timeout_lu_auth_info
- Total time passed: 0.000000 s
- Location Update request causes a GSUP Send Auth Info request to HLR
  MSC <--GERAN-A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
  new conn
DMSC msub_fsm{active}: Allocated
DMSC msc_a{MSC_A_ST_VALIDATE_L3}: Allocated
DMSC msc_a{MSC_A_ST_VALIDATE_L3}: is child of msub_fsm
DMSC msc_a(unknown:GERAN-A:NONE){MSC_A_ST_VALIDATE_L3}: state_chg to MSC_A_ST_VALIDATE_L3
DMSC dummy_msc_i{0}: Allocated
DMSC dummy_msc_i{0}: is child of msub_fsm
DREF msc_a(unknown:GERAN-A:NONE){MSC_A_ST_VALIDATE_L3}: + rx_from_ms: now used by 1 (rx_from_ms)
DBSSAP msc_a(unknown:GERAN-A:NONE){MSC_A_ST_VALIDATE_L3}: RAN decode: COMPL_L3
DRLL msc_a(unknown:GERAN-A:NONE){MSC_A_ST_VALIDATE_L3}: Dispatching 04.08 message: MM GSM48_MT_MM_LOC_UPD_REQUEST
DMM msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: LOCATION UPDATING REQUEST: MI=IMSI-901700000004620 LU-type=IMSI-ATTACH
DMM msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: USIM: old LAI: 001-868-1
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: + mm_rx_loc_upd_req: now used by 2 (rx_from_ms,mm_rx_loc_upd_req)
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: + lu: now used by 3 (rx_from_ms,mm_rx_loc_upd_req,lu)
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: Allocated
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: is child of msc_a(IMSI-901700000004620:GERAN-A:LU)
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
DREF VLR subscr unknown + _lu_fsm_associate_vsub: now used by 1 (_lu_fsm_associate_vsub)
DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
DVLR New subscr, IMSI: 901700000004620
DREF VLR subscr IMSI-901700000004620 + active-conn: now used by 2 (_lu_fsm_associate_vsub,active-conn)
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: Received Event MSC_A_EV_COMPLETE_LAYER_3_OK
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: state_chg to MSC_A_ST_AUTH_CIPH
DREF VLR subscr IMSI-901700000004620 - _lu_fsm_associate_vsub: now used by 1 (active-conn)
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: vlr_loc_upd_node1_pre()
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
DVLR VLR_Authenticate(IMSI-901700000004620:GERAN-A:LU){VLR_SUB_AS_NEEDS_AUTH}: Allocated
DVLR VLR_Authenticate(IMSI-901700000004620:GERAN-A:LU){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU)
DVLR VLR_Authenticate(IMSI-901700000004620:GERAN-A:LU){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f00a0101
DVLR VLR_Authenticate(IMSI-901700000004620:GERAN-A:LU){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: - mm_rx_loc_upd_req: now used by 2 (rx_from_ms,lu)
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: - rx_from_ms: now used by 1 (lu)
  lu_result_sent == 0


- HLR never replies
- At first, we're still waiting
- Total time passed: 0.000423 s
  llist_count(&msub_list) == 1
- Total time passed: 1.000658 s
  llist_count(&msub_list) == 1
- Total time passed: 2.000893 s
  llist_count(&msub_list) == 1
- Total time passed: 3.001128 s
  llist_count(&msub_list) == 1
- Total time passed: 4.001363 s
  llist_count(&msub_list) == 1
- Total time passed: 5.001598 s
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: Timeout of X1
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: Received Event MSC_A_EV_CN_CLOSE
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: - lu: now used by 0 (-)
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: Received Event MSC_A_EV_UNUSED
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: state_chg to MSC_A_ST_RELEASING
DBSSAP msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASING}: Releasing: msc_a use is 0 (-)
DREF VLR subscr IMSI-901700000004620 + msc_a_fsm_releasing_onenter: now used by 2 (active-conn,msc_a_fsm_releasing_onenter)
DREF VLR subscr IMSI-901700000004620 + vlr_subscr_cancel_attach_fsm: now used by 3 (active-conn,msc_a_fsm_releasing_onenter,vlr_subscr_cancel_attach_fsm)
- sending LU Reject for IMSI-901700000004620:GERAN-A:LU, cause 22
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASING}: Received Event MSC_A_EV_CN_CLOSE
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASING}: Event MSC_A_EV_CN_CLOSE not permitted
DREF VLR subscr IMSI-901700000004620 - vlr_subscr_cancel_attach_fsm: now used by 2 (active-conn,msc_a_fsm_releasing_onenter)
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASING}: + wait-Clear-Complete: now used by 1 (wait-Clear-Complete)
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASING}: RAN encode: CLEAR_COMMAND on GERAN-A
DMSC dummy_msc_i(IMSI-901700000004620:GERAN-A:LU){0}: Received Event MSC_I_EV_FROM_A_FORWARD_ACCESS_SIGNALLING_REQUEST
DREF VLR subscr IMSI-901700000004620 - msc_a_fsm_releasing_onenter: now used by 1 (active-conn)
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASING}: transition to state MSC_A_ST_RELEASING not permitted!
- RAN_CONN_TIMEOUT has passed, conn is gone.
  bssap_clear_sent == 1
DBSSAP msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASING}: RAN decode: CLEAR_COMPLETE
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASING}: - wait-Clear-Complete: now used by 0 (-)
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASING}: Received Event MSC_A_EV_UNUSED
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASING}: state_chg to MSC_A_ST_RELEASED
DBSSAP msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASED}: Released: msc_a use is 0 (-)
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_DONE}: Terminating in cascade, depth 2 (cause = OSMO_FSM_TERM_PARENT, caused by: msc_a(IMSI-901700000004620:GERAN-A:LU))
DVLR VLR_Authenticate(IMSI-901700000004620:GERAN-A:LU){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Terminating in cascade, depth 3 (cause = OSMO_FSM_TERM_PARENT, caused by: msc_a(IMSI-901700000004620:GERAN-A:LU))
DVLR VLR_Authenticate(IMSI-901700000004620:GERAN-A:LU){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Removing from parent vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU)
DVLR VLR_Authenticate(IMSI-901700000004620:GERAN-A:LU){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Deferring: will deallocate with msc_a(IMSI-901700000004620:GERAN-A:LU)
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_DONE}: Removing from parent msc_a(IMSI-901700000004620:GERAN-A:LU)
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_DONE}: Deferring: will deallocate with msc_a(IMSI-901700000004620:GERAN-A:LU)
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASED}: Removing from parent msub_fsm
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASED}: max total use count was 3
DMSC msub_fsm{active}: Received Event MSUB_EV_ROLE_TERMINATED
DMSC msub(IMSI-901700000004620) MSC-A terminated
DMSC msub(IMSI-901700000004620) 1 MSC-I still active
DMSC msub_fsm{active}: state_chg to terminating
DMSC msub_fsm{terminating}: Terminating in cascade, depth 2 (cause = OSMO_FSM_TERM_REGULAR, caused by: msc_a(IMSI-901700000004620:GERAN-A:LU))
DMSC dummy_msc_i(IMSI-901700000004620:GERAN-A:LU){0}: Terminating in cascade, depth 3 (cause = OSMO_FSM_TERM_PARENT, caused by: msc_a(IMSI-901700000004620:GERAN-A:LU))
DMSC dummy_msc_i(IMSI-901700000004620:GERAN-A:LU){0}: Removing from parent msub_fsm
DMSC dummy_msc_i(IMSI-901700000004620:GERAN-A:LU){0}: Deferring: will deallocate with msc_a(IMSI-901700000004620:GERAN-A:LU)
DMSC msub(IMSI-901700000004620) Free
DREF VLR subscr IMSI-901700000004620 - active-conn: now used by 0 (-)
DVLR freeing VLR subscr IMSI-901700000004620 (max total use count was 3)
DMSC msub_fsm{terminating}: Deferring: will deallocate with msc_a(IMSI-901700000004620:GERAN-A:LU)
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_RELEASED}: Deallocated, including all deferred deallocations
- msub gone
  llist_count(&msub_list) == 0
  lu_result_sent == 2
===== test_hlr_timeout_lu_auth_info: SUCCESS

full talloc report on 'msgb' (total      0 bytes in   1 blocks)
talloc_total_blocks(tall_bsc_ctx) == 19

===== test_hlr_timeout_lu_upd_loc_result
- Total time passed: 0.000000 s
- Location Update request causes a GSUP LU request to HLR
  MSC <--GERAN-A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
  new conn
DMSC msub_fsm{active}: Allocated
DMSC msc_a{MSC_A_ST_VALIDATE_L3}: Allocated
DMSC msc_a{MSC_A_ST_VALIDATE_L3}: is child of msub_fsm
DMSC msc_a(unknown:GERAN-A:NONE){MSC_A_ST_VALIDATE_L3}: state_chg to MSC_A_ST_VALIDATE_L3
DMSC dummy_msc_i{0}: Allocated
DMSC dummy_msc_i{0}: is child of msub_fsm
DREF msc_a(unknown:GERAN-A:NONE){MSC_A_ST_VALIDATE_L3}: + rx_from_ms: now used by 1 (rx_from_ms)
DBSSAP msc_a(unknown:GERAN-A:NONE){MSC_A_ST_VALIDATE_L3}: RAN decode: COMPL_L3
DRLL msc_a(unknown:GERAN-A:NONE){MSC_A_ST_VALIDATE_L3}: Dispatching 04.08 message: MM GSM48_MT_MM_LOC_UPD_REQUEST
DMM msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: LOCATION UPDATING REQUEST: MI=IMSI-901700000004620 LU-type=IMSI-ATTACH
DMM msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: USIM: old LAI: 001-868-1
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: + mm_rx_loc_upd_req: now used by 2 (rx_from_ms,mm_rx_loc_upd_req)
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: + lu: now used by 3 (rx_from_ms,mm_rx_loc_upd_req,lu)
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: Allocated
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: is child of msc_a(IMSI-901700000004620:GERAN-A:LU)
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
DREF VLR subscr unknown + _lu_fsm_associate_vsub: now used by 1 (_lu_fsm_associate_vsub)
DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
DVLR New subscr, IMSI: 901700000004620
DREF VLR subscr IMSI-901700000004620 + active-conn: now used by 2 (_lu_fsm_associate_vsub,active-conn)
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: Received Event MSC_A_EV_COMPLETE_LAYER_3_OK
DMSC msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_VALIDATE_L3}: state_chg to MSC_A_ST_AUTH_CIPH
DREF VLR subscr IMSI-901700000004620 - _lu_fsm_associate_vsub: now used by 1 (active-conn)
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: vlr_loc_upd_node1_pre()
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
DVLR vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
DVLR upd_hlr_vlr_fsm(IMSI-901700000004620:GERAN-A:LU){UPD_HLR_VLR_S_INIT}: Allocated
DVLR upd_hlr_vlr_fsm(IMSI-901700000004620:GERAN-A:LU){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(IMSI-901700000004620:GERAN-A:LU)
DVLR upd_hlr_vlr_fsm(IMSI-901700000004620:GERAN-A:LU){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f02801020a0101
DVLR upd_hlr_vlr_fsm(IMSI-901700000004620:GERAN-A:LU){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: - mm_rx_loc_upd_req: now used by 2 (rx_from_ms,lu)
DREF msc_a(IMSI-901700000004620:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: - rx_from_ms: now used by 1 (lu)
  lu_result_sent == 0
- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f10a0101
DREF VLR subscr IMSI-901700000004620 + vlr_gsup_rx: now used by 2 (active-conn,vlr_gsup_rx)
DVLR IMSI:901700000004620 has MSISDN:46071
DVLR SUBSCR(IMSI-901700000004620:MSISDN-46071) VLR: update for IMSI=901700000004620 (MSISDN=46071)
GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f00a0101
DREF VLR subscr IMSI-901700000004620:MSISDN-46071 - vlr_gsup_rx: now used by 1 (active-conn)
<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
  lu_result_sent == 0


- HLR never sends GSUP _UPDATE_LOCATION_RESULT
- At first, we're still waiting
- Total time passed: 0.000423 s
  llist_count(&msub_list) == 1
  lu_result_sent == 0
- Total time passed: 1.000658 s
  llist_count(&msub_list) == 1
  lu_result_sent == 0
- Total time passed: 2.000893 s
  llist_count(&msub_list) == 1
  lu_result_sent == 0
- Total time passed: 3.001128 s
  llist_count(&msub_list) == 1
  lu_result_sent == 0
- Total time passed: 4.001363 s
  llist_count(&msub_list) == 1
  lu_result_sent == 0
- Total time passed: 5.001598 s
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: Timeout of X1
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: Received Event MSC_A_EV_CN_CLOSE
DREF msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: - lu: now used by 0 (-)
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: Received Event MSC_A_EV_UNUSED
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_AUTH_CIPH}: state_chg to MSC_A_ST_RELEASING
DBSSAP msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASING}: Releasing: msc_a use is 0 (-)
DREF VLR subscr IMSI-901700000004620:MSISDN-46071 + msc_a_fsm_releasing_onenter: now used by 2 (active-conn,msc_a_fsm_releasing_onenter)
DREF VLR subscr IMSI-901700000004620:MSISDN-46071 + vlr_subscr_cancel_attach_fsm: now used by 3 (active-conn,msc_a_fsm_releasing_onenter,vlr_subscr_cancel_attach_fsm)
- sending LU Reject for IMSI-901700000004620:MSISDN-46071:GERAN-A:LU, cause 22
DVLR vlr_lu_fsm(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_DONE
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASING}: Received Event MSC_A_EV_CN_CLOSE
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASING}: Event MSC_A_EV_CN_CLOSE not permitted
DREF VLR subscr IMSI-901700000004620:MSISDN-46071 - vlr_subscr_cancel_attach_fsm: now used by 2 (active-conn,msc_a_fsm_releasing_onenter)
DREF msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASING}: + wait-Clear-Complete: now used by 1 (wait-Clear-Complete)
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASING}: RAN encode: CLEAR_COMMAND on GERAN-A
DMSC dummy_msc_i(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){0}: Received Event MSC_I_EV_FROM_A_FORWARD_ACCESS_SIGNALLING_REQUEST
DREF VLR subscr IMSI-901700000004620:MSISDN-46071 - msc_a_fsm_releasing_onenter: now used by 1 (active-conn)
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASING}: transition to state MSC_A_ST_RELEASING not permitted!
- RAN_CONN_TIMEOUT has passed, conn is gone.
  bssap_clear_sent == 1
DBSSAP msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASING}: RAN decode: CLEAR_COMPLETE
DREF msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASING}: - wait-Clear-Complete: now used by 0 (-)
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASING}: Received Event MSC_A_EV_UNUSED
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASING}: state_chg to MSC_A_ST_RELEASED
DBSSAP msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASED}: Released: msc_a use is 0 (-)
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR vlr_lu_fsm(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){VLR_ULA_S_DONE}: Terminating in cascade, depth 2 (cause = OSMO_FSM_TERM_PARENT, caused by: msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU))
DVLR upd_hlr_vlr_fsm(IMSI-901700000004620:GERAN-A:LU){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Terminating in cascade, depth 3 (cause = OSMO_FSM_TERM_PARENT, caused by: msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU))
DVLR upd_hlr_vlr_fsm(IMSI-901700000004620:GERAN-A:LU){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Removing from parent vlr_lu_fsm(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU)
DVLR upd_hlr_vlr_fsm(IMSI-901700000004620:GERAN-A:LU){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Deferring: will deallocate with msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU)
DVLR vlr_lu_fsm(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){VLR_ULA_S_DONE}: Removing from parent msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU)
DVLR vlr_lu_fsm(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
DVLR vlr_lu_fsm(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){VLR_ULA_S_DONE}: Deferring: will deallocate with msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU)
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASED}: Removing from parent msub_fsm
DREF msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASED}: max total use count was 3
DMSC msub_fsm{active}: Received Event MSUB_EV_ROLE_TERMINATED
DMSC msub(IMSI-901700000004620:MSISDN-46071) MSC-A terminated
DMSC msub(IMSI-901700000004620:MSISDN-46071) 1 MSC-I still active
DMSC msub_fsm{active}: state_chg to terminating
DMSC msub_fsm{terminating}: Terminating in cascade, depth 2 (cause = OSMO_FSM_TERM_REGULAR, caused by: msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU))
DMSC dummy_msc_i(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){0}: Terminating in cascade, depth 3 (cause = OSMO_FSM_TERM_PARENT, caused by: msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU))
DMSC dummy_msc_i(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){0}: Removing from parent msub_fsm
DMSC dummy_msc_i(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){0}: Deferring: will deallocate with msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU)
DMSC msub(IMSI-901700000004620:MSISDN-46071) Free
DREF VLR subscr IMSI-901700000004620:MSISDN-46071 - active-conn: now used by 0 (-)
DVLR freeing VLR subscr IMSI-901700000004620:MSISDN-46071 (max total use count was 3)
DMSC msub_fsm{terminating}: Deferring: will deallocate with msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU)
DMSC msc_a(IMSI-901700000004620:MSISDN-46071:GERAN-A:LU){MSC_A_ST_RELEASED}: Deallocated, including all deferred deallocations
- msub gone
  llist_count(&msub_list) == 0
  lu_result_sent == 2
===== test_hlr_timeout_lu_upd_loc_result: SUCCESS

full talloc report on 'msgb' (total      0 bytes in   1 blocks)
talloc_total_blocks(tall_bsc_ctx) == 19

full talloc report on 'msgb' (total      0 bytes in   1 blocks)
talloc_total_blocks(tall_bsc_ctx) == 19