Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / 84da6b1edb806ac0d7b8a0c40c80f83c4b1d92b9 / . / tests / msc_vlr / msc_vlr_test_ms_timeout.err
blob: 046548c1eb204ec8e36b0278af2f415f89b3ec66 [file] [log] [blame]
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1===== test_ms_timeout_lu_auth_resp
2- Total time passed: 0.000000 s
3- Location Update request causes a GSUP Send Auth Info request to HLR
4 rx from MS: pdisc=0x05 msg_type=0x08
5 new conn
6DREF unknown: MSC conn use + 1 == 1
7DRLL Dispatching 04.08 message, pdisc=5
8DREF unknown: MSC conn use + 1 == 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]9DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
10DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
11DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]12DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
13DMM LU/new-LAC: 1/0
14DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
15DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
16DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
17DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
18DREF VLR subscr unknown usage increases to: 1
19DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
20DVLR New subscr, IMSI: 901700000004620
21DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]22DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]23DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
24DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
25DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
26DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
27DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
28DVLR GSUP tx: 08010809710000004026f0
29GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
30DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]31DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]32DREF IMSI:901700000004620: MSC conn use - 1 == 1
33 lu_result_sent == 0
34- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
35<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a800
36DVLR GSUP rx 47: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a800
37DREF VLR subscr IMSI:901700000004620 usage increases to: 2
38DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
39DVLR SUBSCR(IMSI:901700000004620) Received 1 auth tuples
40DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
41DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
42- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
43- ...rand=585df1ae287f6e273dce07090d61320b
44- ...expecting sres=2d8b2c3e
45DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
46<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
47 auth_request_sent == 1
48 lu_result_sent == 0
49---
50- MS fails to send an Authentication Response
51- At first, we're still waiting
52- Total time passed: 0.000423 s
53 llist_count(&net->subscr_conns) == 1
54 lu_result_sent == 0
55- Total time passed: 1.000658 s
56 llist_count(&net->subscr_conns) == 1
57 lu_result_sent == 0
58- Total time passed: 2.000893 s
59 llist_count(&net->subscr_conns) == 1
60 lu_result_sent == 0
61- Total time passed: 3.001128 s
62 llist_count(&net->subscr_conns) == 1
63 lu_result_sent == 0
64- Total time passed: 4.001363 s
65 llist_count(&net->subscr_conns) == 1
66 lu_result_sent == 0
67- Total time passed: 5.001598 s
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]68DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Timeout of T0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]69DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Connection timed out
70- sending LU Reject for IMSI:901700000004620, cause 22
71DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]72DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
73DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
74DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Close event, cause 1
75DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
76DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]77DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
78DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Terminating (cause = OSMO_FSM_TERM_PARENT)
79DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Removing from parent vlr_lu_fsm(901700000004620)
80DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Freeing instance
81DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Deallocated
82DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
83DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
84DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
85DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
86DMM msc_subscr_conn_close(vsub=IMSI:901700000004620, cause=2): no conn fsm, releasing directly without release event.
87DREF IMSI:901700000004620: MSC conn use - 1 == 0
88DRLL subscr IMSI:901700000004620: Freeing subscriber connection
89DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
90DREF freeing VLR subscr IMSI:901700000004620
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]91DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
92DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
93DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Received Event SUBSCR_CONN_E_CN_CLOSE
94DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Event SUBSCR_CONN_E_CN_CLOSE not permitted
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]95- SUBSCR_CONN_TIMEOUT has passed, conn is gone.
96 llist_count(&net->subscr_conns) == 0
97 lu_result_sent == 2
98===== test_ms_timeout_lu_auth_resp: SUCCESS
99
100full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]101talloc_total_blocks(tall_bsc_ctx) == 9
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]102
103===== test_ms_timeout_cm_auth_resp
104- Total time passed: 0.000000 s
105- Location Update request causes a GSUP Send Auth Info request to HLR
106 rx from MS: pdisc=0x05 msg_type=0x08
107 new conn
108DREF unknown: MSC conn use + 1 == 1
109DRLL Dispatching 04.08 message, pdisc=5
110DREF unknown: MSC conn use + 1 == 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]111DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
112DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
113DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]114DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
115DMM LU/new-LAC: 1/0
116DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
117DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
118DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
119DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
120DREF VLR subscr unknown usage increases to: 1
121DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
122DVLR New subscr, IMSI: 901700000004620
123DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]124DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]125DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
126DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
127DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
128DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
129DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
130DVLR GSUP tx: 08010809710000004026f0
131GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
132DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]133DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]134DREF IMSI:901700000004620: MSC conn use - 1 == 1
135 lu_result_sent == 0
136- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
137<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
138DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
139DREF VLR subscr IMSI:901700000004620 usage increases to: 2
140DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
141DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
142DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
143DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
144- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
145- ...rand=585df1ae287f6e273dce07090d61320b
146- ...expecting sres=2d8b2c3e
147DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
148<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
149 auth_request_sent == 1
150 lu_result_sent == 0
151- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
152 rx from MS: pdisc=0x05 msg_type=0x54
153DREF IMSI:901700000004620: MSC conn use + 1 == 2
154DRLL Dispatching 04.08 message, pdisc=5
155DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
156DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
157DVLR SUBSCR(IMSI:901700000004620) received res: 2d 8b 2c 3e
158DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
159DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
160DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
161DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
162DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
163DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
164DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
165DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
166DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
167DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
168DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
169DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
170DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
171DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
172DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
173DVLR GSUP tx: 04010809710000004026f0
174GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
175DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]176DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]177DREF IMSI:901700000004620: MSC conn use - 1 == 1
178 lu_result_sent == 0
179- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
180<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
181DVLR GSUP rx 17: 10010809710000004026f00804036470f1
182DREF VLR subscr IMSI:901700000004620 usage increases to: 2
183DVLR IMSI:901700000004620 has MSISDN:46071
184DVLR GSUP tx: 12010809710000004026f0
185GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
186DREF VLR subscr MSISDN:46071 usage decreases to: 1
187<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
188 lu_result_sent == 0
189- HLR also sends GSUP _UPDATE_LOCATION_RESULT
190<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
191DVLR GSUP rx 11: 06010809710000004026f0
192DREF VLR subscr MSISDN:46071 usage increases to: 2
193DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
194DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
195DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
196DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
197DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
198DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
199DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
200DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
201DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
202DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
203DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
204DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
205DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
206DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
207DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
208DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
209DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
210DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
211DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
212DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
213DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
214DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
215- sending LU Accept for MSISDN:46071
216DREF VLR subscr MSISDN:46071 usage increases to: 3
217DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
218DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
219DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
220DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
221DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
222DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
223DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]224DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
225DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
226DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
227DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
228DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
229DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
230DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]231DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
232DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
233DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
234DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
235DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
236DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
237DREF MSISDN:46071: MSC conn use - 1 == 0
238DRLL subscr MSISDN:46071: Freeing subscriber connection
239DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]240DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
241DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]242DREF VLR subscr MSISDN:46071 usage decreases to: 1
243<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
244- LU was successful, and the conn has already been closed
245 lu_result_sent == 1
246 llist_count(&net->subscr_conns) == 0
247---
248- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
249 rx from MS: pdisc=0x05 msg_type=0x24
250 new conn
251DREF unknown: MSC conn use + 1 == 1
252DRLL Dispatching 04.08 message, pdisc=5
253DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
254DREF unknown: MSC conn use + 1 == 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]255DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
256DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
257DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]258DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
259DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
260DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
261DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
262DREF VLR subscr MSISDN:46071 usage increases to: 2
263DREF VLR subscr MSISDN:46071 usage increases to: 3
264DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
265DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
266DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
267DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000004620)
268DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
269DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
270DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
271- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
272- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
273- ...expecting sres=20bde240
274DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]275DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]276DREF MSISDN:46071: MSC conn use - 1 == 1
277 cm_service_result_sent == 0
278 auth_request_sent == 1
279---
280- MS fails to send an Authentication Response
281- At first, we're still waiting
282- Total time passed: 0.000423 s
283 llist_count(&net->subscr_conns) == 1
284 cm_service_result_sent == 0
285- Total time passed: 1.000658 s
286 llist_count(&net->subscr_conns) == 1
287 cm_service_result_sent == 0
288- Total time passed: 2.000893 s
289 llist_count(&net->subscr_conns) == 1
290 cm_service_result_sent == 0
291- Total time passed: 3.001128 s
292 llist_count(&net->subscr_conns) == 1
293 cm_service_result_sent == 0
294- Total time passed: 4.001363 s
295 llist_count(&net->subscr_conns) == 1
296 cm_service_result_sent == 0
297- Total time passed: 5.001598 s
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]298DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Timeout of T0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]299DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Connection timed out
300DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_TIMEOUT)
301DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
302DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_TIMEOUT
303- sending CM Service Reject for MSISDN:46071, result VLR_PR_ARQ_RES_TIMEOUT
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]304DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
305DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
306DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Close event, cause 2
307DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
308DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]309DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
310DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Terminating (cause = OSMO_FSM_TERM_PARENT)
311DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Removing from parent Process_Access_Request_VLR(901700000004620)
312DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Freeing instance
313DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Deallocated
314DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
315DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
316DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
317DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
318DREF MSISDN:46071: MSC conn use - 1 == 0
319DRLL subscr MSISDN:46071: Freeing subscriber connection
320DREF VLR subscr MSISDN:46071 usage decreases to: 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]321DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
322DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
323DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Received Event SUBSCR_CONN_E_CN_CLOSE
324DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Event SUBSCR_CONN_E_CN_CLOSE not permitted
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]325- SUBSCR_CONN_TIMEOUT has passed, conn is gone.
326 llist_count(&net->subscr_conns) == 0
327 cm_service_result_sent == 2
328DREF freeing VLR subscr MSISDN:46071
329===== test_ms_timeout_cm_auth_resp: SUCCESS
330
331full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame^]332talloc_total_blocks(tall_bsc_ctx) == 9
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]333
334full talloc report on 'msgb' (total 0 bytes in 1 blocks)
335talloc_total_blocks(tall_bsc_ctx) == 9
336