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