summaryrefslogtreecommitdiffstats
path: root/openbsc/tests/msc_vlr/msc_vlr_test_hlr_timeout.err
blob: dee4bfbbcde141ec0ba1fb497ec2cfc67985f04e (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
===== 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 <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
  new conn
DREF unknown: MSC conn use + 1 == 1
DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
DREF unknown: MSC conn use + 1 == 2
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
DMM LU/new-LAC: 1/0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
DREF VLR subscr unknown usage increases to: 1
DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
DVLR New subscr, IMSI: 901700000004620
DREF VLR subscr IMSI:901700000004620 usage increases to: 2
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
DVLR GSUP tx: 08010809710000004026f0
GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
  lu_result_sent == 0
---
- HLR never replies
- At first, we're still waiting
- Total time passed: 0.000423 s
  llist_count(&net->subscr_conns) == 1
- Total time passed: 1.000658 s
  llist_count(&net->subscr_conns) == 1
- Total time passed: 2.000893 s
  llist_count(&net->subscr_conns) == 1
- Total time passed: 3.001128 s
  llist_count(&net->subscr_conns) == 1
- Total time passed: 4.001363 s
  llist_count(&net->subscr_conns) == 1
- Total time passed: 5.001598 s
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Timeout of T0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Connection timed out
- sending LU Reject for IMSI:901700000004620, cause 22
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Close event, cause 1
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Removing from parent vlr_lu_fsm(901700000004620)
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Freeing instance
DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Deallocated
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
DREF IMSI:901700000004620: MSC conn use - 1 == 0
DRLL subscr IMSI:901700000004620: Freeing subscriber connection
DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
DREF freeing VLR subscr IMSI:901700000004620
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Received Event SUBSCR_CONN_E_CN_CLOSE
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Event SUBSCR_CONN_E_CN_CLOSE not permitted
- SUBSCR_CONN_TIMEOUT has passed, conn is gone.
  llist_count(&net->subscr_conns) == 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) == 9

===== test_hlr_timeout_lu_upd_loc_result
- Total time passed: 0.000000 s
- Location Update request causes a GSUP LU request to HLR
  MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
  new conn
DREF unknown: MSC conn use + 1 == 1
DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
DREF unknown: MSC conn use + 1 == 2
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
DMM LU/new-LAC: 1/0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
DREF VLR subscr unknown usage increases to: 1
DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
DVLR New subscr, IMSI: 901700000004620
DREF VLR subscr IMSI:901700000004620 usage increases to: 2
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
DVLR GSUP tx: 04010809710000004026f0
GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
DREF IMSI:901700000004620: MSC conn use - 1 == 1
  lu_result_sent == 0
- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
DVLR GSUP rx 17: 10010809710000004026f00804036470f1
DREF VLR subscr IMSI:901700000004620 usage increases to: 2
DVLR IMSI:901700000004620 has MSISDN:46071
DVLR GSUP tx: 12010809710000004026f0
GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
DREF VLR subscr MSISDN:46071 usage decreases to: 1
<-- 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(&net->subscr_conns) == 1
  lu_result_sent == 0
- Total time passed: 1.000658 s
  llist_count(&net->subscr_conns) == 1
  lu_result_sent == 0
- Total time passed: 2.000893 s
  llist_count(&net->subscr_conns) == 1
  lu_result_sent == 0
- Total time passed: 3.001128 s
  llist_count(&net->subscr_conns) == 1
  lu_result_sent == 0
- Total time passed: 4.001363 s
  llist_count(&net->subscr_conns) == 1
  lu_result_sent == 0
- Total time passed: 5.001598 s
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Timeout of T0
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Connection timed out
- sending LU Reject for MSISDN:46071, cause 22
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_DONE
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Close event, cause 1
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Terminating (cause = OSMO_FSM_TERM_PARENT)
DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Removing from parent vlr_lu_fsm(901700000004620)
DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Freeing instance
DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Deallocated
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
DREF MSISDN:46071: MSC conn use - 1 == 0
DRLL subscr MSISDN:46071: Freeing subscriber connection
DREF VLR subscr MSISDN:46071 usage decreases to: 0
DREF freeing VLR subscr MSISDN:46071
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Received Event SUBSCR_CONN_E_CN_CLOSE
DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Event SUBSCR_CONN_E_CN_CLOSE not permitted
- SUBSCR_CONN_TIMEOUT has passed, conn is gone.
  llist_count(&net->subscr_conns) == 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) == 9

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