blob: c2efa9e8a0b3cc8c8f4c62b074893dfc8a868f22 [file] [log] [blame]
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001===== test_gsm_authen
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01003 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01004 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01005DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01006DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01007DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02008DMM 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 +010011DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +010012DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010013DVLR 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 +020021DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010022DVLR 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 +020030DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +010031DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010032 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
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +010040DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010041- 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
Neels Hofmeyr78ada642017-03-10 02:15:20 +010058DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
59DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
60DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
61DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
62DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
63DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +010064DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
65DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010066 lu_result_sent == 0
67- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +010068 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +010069DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +010070DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010071DMM 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
Neels Hofmeyra9099bc2018-03-10 04:22:50 +010073DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010074DVLR 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 +020092DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +010093DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010094 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
Maxa263bb22017-12-27 13:23:44 +0100100DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100101DVLR GSUP tx: 12010809710000004026f0
102GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
103DREF VLR subscr MSISDN:46071 usage decreases to: 1
104<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
105 lu_result_sent == 0
106- HLR also sends GSUP _UPDATE_LOCATION_RESULT
107<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
108DVLR GSUP rx 11: 06010809710000004026f0
109DREF VLR subscr MSISDN:46071 usage increases to: 2
110DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
111DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
112DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
113DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
114DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
115DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
116DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
117DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
118DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
119DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
120DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
121DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
122DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
123DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
124DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
125DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
126DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
127DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
128DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
129DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
130DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
131DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
132- sending LU Accept for MSISDN:46071
133DREF VLR subscr MSISDN:46071 usage increases to: 3
134DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
135DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
136DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
137DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
138DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
139DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
140DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200141DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
142DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
143DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
144DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
145DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
146DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
147DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100148DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
149DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
150DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
151DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
152DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
153DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200154- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100155DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100156DRLL subscr MSISDN:46071: Freeing subscriber connection
157DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200158DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
159DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100160DREF VLR subscr MSISDN:46071 usage decreases to: 1
161<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
Philipp Maierfbf66102017-04-09 12:32:51 +0200162 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100163- LU was successful, and the conn has already been closed
164 lu_result_sent == 1
165 llist_count(&net->subscr_conns) == 0
166---
167- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100168 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100169 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100170DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100171DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100172DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100173DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200174DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
175DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
176DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100177DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
178DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
179DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
180DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
181DREF VLR subscr MSISDN:46071 usage increases to: 2
182DREF VLR subscr MSISDN:46071 usage increases to: 3
183DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
184DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
185DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
186DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000004620)
187DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
188DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100189DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100190- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
191- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
192- ...expecting sres=20bde240
193DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200194DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100195DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100196 cm_service_result_sent == 0
197 auth_request_sent == 1
198- needs auth, not yet accepted
199msc_subscr_conn_is_accepted() == false
200 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100201DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
202DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
203DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
204DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
205DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
206DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100207DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
208DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100209- MS sends Authen Response, VLR accepts with a CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100210 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100211DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100212DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100213DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
214DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100215DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: 20bde240 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100216DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
217DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
218DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
219DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
220DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000004620)
221DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
222DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
223DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
224DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
225DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
226DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
227DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
228DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
229DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
230DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
231DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
232DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
233DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
234- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200235DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
236DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
237DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
238DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
239DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
240DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
241DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
242DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100243DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100244 cm_service_result_sent == 1
245- a USSD request is serviced
246 expecting USSD:
247 Your extension is 46071
Harald Welte80315ef2018-01-24 22:53:00 +0100248 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100249DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +0100250DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
251DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200252DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
253DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100254DMM USSD: Own number requested
255DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200256DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100257- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100258- DTAP matches expected message
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200259DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
260DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
261DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
262DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100263DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
264DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
265DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
266DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
267DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200268- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100269DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200270DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
271DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100272DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100273DRLL subscr MSISDN:46071: Freeing subscriber connection
274DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200275 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100276- all requests serviced, conn has been released
277 llist_count(&net->subscr_conns) == 0
278---
279- an SMS is sent, MS is paged
280DREF VLR subscr MSISDN:46071 usage increases to: 2
281 llist_count(&vsub->cs.requests) == 0
282DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200283DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100284 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200285 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100286DREF VLR subscr MSISDN:46071 usage increases to: 4
287 llist_count(&vsub->cs.requests) == 1
288DREF VLR subscr MSISDN:46071 usage decreases to: 3
289 paging_sent == 1
290 paging_stopped == 0
291- the subscriber and its pending request should remain
292DREF VLR subscr MSISDN:46071 usage increases to: 4
293 llist_count(&vsub->cs.requests) == 1
294DREF VLR subscr MSISDN:46071 usage decreases to: 3
295- MS replies with Paging Response, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100296 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100297 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100298DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100299DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100300DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100301DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200302DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
303DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
304DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100305DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
306DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
307DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
308DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
309DREF VLR subscr MSISDN:46071 usage increases to: 4
310DREF VLR subscr MSISDN:46071 usage increases to: 5
311DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
312DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
313DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
314DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000004620)
315DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
316DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100317DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100318- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
319- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
320- ...expecting sres=a29514ae
321DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200322DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100323DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100324 auth_request_sent == 1
325- needs auth, not yet accepted
326msc_subscr_conn_is_accepted() == false
327 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100328DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
329DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
330DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
331DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
332DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
333DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100334DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
335DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100336- MS sends Authen Response, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100337 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100338DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100339DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100340DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
341DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100342DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: a29514ae (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100343DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
344DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
345DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
346DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
347DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000004620)
348DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
349DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
350DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
351DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
352DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
353DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
354DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
355DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
356DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
357DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
358DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
359DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
360DVLR 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 +0200361DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
362DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
363DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
364DPAG Paging success for MSISDN:46071 (event=0)
365DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100366DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100367DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100368DREF MSISDN:46071: MSC conn use + trans_sms == 3 (0x16)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200369DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100370- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100371- DTAP matches expected message
372DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200373DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
Harald Welte80315ef2018-01-24 22:53:00 +0100374DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: SMS
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200375DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
Harald Welte80315ef2018-01-24 22:53:00 +0100376DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100377DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100378 dtap_tx_confirmed == 1
379 paging_stopped == 1
380- SMS was delivered, no requests pending for subscr
381DREF VLR subscr MSISDN:46071 usage increases to: 5
382 llist_count(&vsub->cs.requests) == 0
383DREF VLR subscr MSISDN:46071 usage decreases to: 4
384- conn is still open to wait for SMS ack dance
385 llist_count(&net->subscr_conns) == 1
386- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100387 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100388DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100389DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200390DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
391DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
392DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
Harald Welte80315ef2018-01-24 22:53:00 +0100393DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100394DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100395 llist_count(&net->subscr_conns) == 1
396- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100397 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100398DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100399DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200400DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
401DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100402- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100403- DTAP matches expected message
404DREF VLR subscr MSISDN:46071 usage decreases to: 3
405DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100406DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200407DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
408DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
409DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
410DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100411DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
412DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
413DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
414DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
415DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200416- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100417DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200418DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
419DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100420DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100421DRLL subscr MSISDN:46071: Freeing subscriber connection
422DREF VLR subscr MSISDN:46071 usage decreases to: 1
423 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200424 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100425- SMS is done, conn is gone
426 llist_count(&net->subscr_conns) == 0
427---
428- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100429 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100430 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100431DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100432DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100433DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
434DREF VLR subscr MSISDN:46071 usage increases to: 2
435DMM IMSI DETACH for MSISDN:46071
436DREF VLR subscr MSISDN:46071 usage decreases to: 1
437DREF VLR subscr MSISDN:46071 usage decreases to: 0
438DREF freeing VLR subscr MSISDN:46071
439DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200440- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100441DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100442DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +0200443 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100444 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100445===== test_gsm_authen: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100446
447full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte23466192018-02-14 00:19:06 +0100448talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100449
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100450===== test_gsm_authen_tmsi
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100451- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100452 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100453 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100454DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100455DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100456DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200457DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
458DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
459DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100460DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100461DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100462DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
463DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
464DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
465DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
466DREF VLR subscr unknown usage increases to: 1
467DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
468DVLR New subscr, IMSI: 901700000004620
469DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200470DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100471DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
472DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
473DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
474DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
475DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
476DVLR GSUP tx: 08010809710000004026f0
477GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
478DVLR 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 +0200479DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100480DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100481 lu_result_sent == 0
482- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
483<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
484DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
485DREF VLR subscr IMSI:901700000004620 usage increases to: 2
486DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
487DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
488DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100489DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100490- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
491- ...rand=585df1ae287f6e273dce07090d61320b
492- ...expecting sres=2d8b2c3e
493DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
494<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
495 auth_request_sent == 1
496 lu_result_sent == 0
497- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
498<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
499DVLR GSUP rx 11: 06010809710000004026f0
500DREF VLR subscr IMSI:901700000004620 usage increases to: 2
501DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
502DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
503DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
504<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
505msc_subscr_conn_is_accepted() == false
506 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100507DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
508DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
509DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
510DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
511DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
512DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100513DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
514DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100515 lu_result_sent == 0
516- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100517 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100518DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100519DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100520DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
521DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100522DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100523DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
524DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
525DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
526DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
527DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
528DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
529DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
530DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
531DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
532DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
533DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
534DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
535DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
536DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
537DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
538DVLR GSUP tx: 04010809710000004026f0
539GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
540DVLR 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 +0200541DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100542DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100543 lu_result_sent == 0
544- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
545<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
546DVLR GSUP rx 17: 10010809710000004026f00804036470f1
547DREF VLR subscr IMSI:901700000004620 usage increases to: 2
548DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100549DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100550DVLR GSUP tx: 12010809710000004026f0
551GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
552DREF VLR subscr MSISDN:46071 usage decreases to: 1
553<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
554 lu_result_sent == 0
555- HLR also sends GSUP _UPDATE_LOCATION_RESULT
556<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
557DVLR GSUP rx 11: 06010809710000004026f0
558DREF VLR subscr MSISDN:46071 usage increases to: 2
559DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
560DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
561DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
562DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
563DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
564DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
565DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
566DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
567DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
568DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
569DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
570DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
571DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
572DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
573DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
574DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
575DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
576DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
577DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
578DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
579DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
580DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
581DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
582DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
583- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
584DREF VLR subscr MSISDN:46071 usage decreases to: 1
585<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
586- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
587 llist_count(&net->subscr_conns) == 1
588 lu_result_sent == 1
589msc_subscr_conn_is_accepted() == false
590 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100591DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
592DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
593DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
594DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
595DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
596DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100597DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
598DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100599- even though the TMSI is not acked, we can already find the subscr with it
600DREF VLR subscr MSISDN:46071 usage increases to: 2
601 vsub != NULL == 1
602 strcmp(vsub->imsi, imsi) == 0
603 vsub->tmsi_new == 0x03020100
604 vsub->tmsi == 0xffffffff
605DREF VLR subscr MSISDN:46071 usage decreases to: 1
606- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100607 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100608DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100609DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100610DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
611DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
612DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
613DREF VLR subscr MSISDN:46071 usage increases to: 2
614DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
615DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
616DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
617DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
618DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
619DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
620DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200621DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
622DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
623DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
624DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
625DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
626DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
627DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100628DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
629DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
630DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
631DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
632DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
633DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200634- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100635DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200636DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
637DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100638DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100639DRLL subscr MSISDN:46071: Freeing subscriber connection
640DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200641 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100642- LU was successful, and the conn has already been closed
643 llist_count(&net->subscr_conns) == 0
644- Subscriber has the new TMSI
645DREF VLR subscr MSISDN:46071 usage increases to: 2
646 vsub != NULL == 1
647 strcmp(vsub->imsi, imsi) == 0
648 vsub->tmsi_new == 0xffffffff
649 vsub->tmsi == 0x03020100
650DREF VLR subscr MSISDN:46071 usage decreases to: 1
651---
652- after a while, a new conn sends a CM Service Request using above TMSI. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100653 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100654 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100655DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100656DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100657DMM <- CM SERVICE REQUEST serv_type=0x08 MI(TMSI)=50462976
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100658DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200659DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
660DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
661DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100662DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
663DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
664DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
665DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
666DREF VLR subscr MSISDN:46071 usage increases to: 2
667DREF VLR subscr MSISDN:46071 usage increases to: 3
668DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
669DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
670DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
671DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(50462976)
672DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
673DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100674DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100675- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=1 auth_types=0x1 and...
676- ...rand=12aca96fb4ffdea5c985cbafa9b6e18b
677- ...expecting sres=20bde240
678DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200679DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100680DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100681 cm_service_result_sent == 0
682 auth_request_sent == 1
683- needs auth, not yet accepted
684msc_subscr_conn_is_accepted() == false
685 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100686DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
687DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
688DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
689DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
690DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
691DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100692DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
693DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100694- MS sends Authen Response, VLR accepts with a CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100695 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100696DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100697DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100698DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 20bde240)
699DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100700DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: 20bde240 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100701DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
702DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
703DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
704DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
705DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(50462976)
706DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
707DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
708DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
709DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
710DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
711DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
712DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
713DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
714DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
715DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
716DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
717DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
718DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
719- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200720DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
721DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
722DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
723DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
724DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
725DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
726DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
727DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100728DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100729 cm_service_result_sent == 1
730- a USSD request is serviced
731 expecting USSD:
732 Your extension is 46071
Harald Welte80315ef2018-01-24 22:53:00 +0100733 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100734DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +0100735DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
736DMM MSISDN:46071: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200737DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
738DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100739DMM USSD: Own number requested
740DMM MSISDN:46071: MSISDN = 46071
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200741DMSC msc_tx 43 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100742- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d27310cd06bbc51a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100743- DTAP matches expected message
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200744DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
745DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
746DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
747DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100748DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
749DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
750DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
751DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
752DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200753- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100754DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200755DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
756DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100757DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100758DRLL subscr MSISDN:46071: Freeing subscriber connection
759DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200760 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100761- all requests serviced, conn has been released
762 llist_count(&net->subscr_conns) == 0
763---
764- an SMS is sent, MS is paged
765DREF VLR subscr MSISDN:46071 usage increases to: 2
766 llist_count(&vsub->cs.requests) == 0
767DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200768DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100769 RAN_GERAN_A sends out paging request to IMSI 901700000004620, TMSI 0x03020100, LAC 23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100770 paging_expecting_tmsi == 0x03020100
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100771DREF VLR subscr MSISDN:46071 usage increases to: 4
772 llist_count(&vsub->cs.requests) == 1
773DREF VLR subscr MSISDN:46071 usage decreases to: 3
774 paging_sent == 1
775 paging_stopped == 0
776- the subscriber and its pending request should remain
777DREF VLR subscr MSISDN:46071 usage increases to: 4
778 llist_count(&vsub->cs.requests) == 1
779DREF VLR subscr MSISDN:46071 usage decreases to: 3
780- MS replies with Paging Response using TMSI, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100781 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100782 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100783DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100784DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100785DRR PAGING RESPONSE: MI(TMSI)=50462976
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100786DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200787DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
788DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
789DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100790DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Allocated
791DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: is child of Subscr_Conn(50462976)
792DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
793DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
794DREF VLR subscr MSISDN:46071 usage increases to: 4
795DREF VLR subscr MSISDN:46071 usage increases to: 5
796DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
797DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
798DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
799DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(50462976)
800DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
801DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100802DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100803- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=2 auth_types=0x1 and...
804- ...rand=e7c03ba7cf0e2fde82b2dc4d63077d42
805- ...expecting sres=a29514ae
806DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200807DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100808DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100809 auth_request_sent == 1
810- needs auth, not yet accepted
811msc_subscr_conn_is_accepted() == false
812 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100813DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
814DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
815DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
816DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
817DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
818DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100819DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
820DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100821- MS sends Authen Response, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100822 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100823DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100824DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100825DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = a29514ae)
826DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100827DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: a29514ae (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100828DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
829DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
830DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
831DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
832DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(50462976)
833DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
834DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
835DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
836DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
837DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
838DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
839DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
840DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
841DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
842DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
843DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
844DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
845DVLR 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 +0200846DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
847DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
848DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
849DPAG Paging success for MSISDN:46071 (event=0)
850DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100851DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100852DREF VLR subscr MSISDN:46071 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100853DREF MSISDN:46071: MSC conn use + trans_sms == 3 (0x16)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200854DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100855- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100856- DTAP matches expected message
857DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200858DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
Harald Welte80315ef2018-01-24 22:53:00 +0100859DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: SMS
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200860DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
Harald Welte80315ef2018-01-24 22:53:00 +0100861DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100862DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100863 dtap_tx_confirmed == 1
864 paging_stopped == 1
865- SMS was delivered, no requests pending for subscr
866DREF VLR subscr MSISDN:46071 usage increases to: 5
867 llist_count(&vsub->cs.requests) == 0
868DREF VLR subscr MSISDN:46071 usage decreases to: 4
869- conn is still open to wait for SMS ack dance
870 llist_count(&net->subscr_conns) == 1
871- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100872 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100873DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100874DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200875DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
876DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
877DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
Harald Welte80315ef2018-01-24 22:53:00 +0100878DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100879DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100880 llist_count(&net->subscr_conns) == 1
881- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100882 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100883DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100884DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200885DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
886DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100887- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100888- DTAP matches expected message
889DREF VLR subscr MSISDN:46071 usage decreases to: 3
890DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100891DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200892DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
893DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
894DMM Subscr_Conn(50462976){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
895DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100896DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
897DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(50462976)
898DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Freeing instance
899DVLR Process_Access_Request_VLR(50462976){PR_ARQ_S_DONE}: Deallocated
900DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200901- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100902DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200903DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
904DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100905DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100906DRLL subscr MSISDN:46071: Freeing subscriber connection
907DREF VLR subscr MSISDN:46071 usage decreases to: 1
908 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200909 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100910- SMS is done, conn is gone
911 llist_count(&net->subscr_conns) == 0
912---
913- subscriber sends LU Request, this time with the TMSI
914- Location Update request causes an Auth Req to MS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100915 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100916 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100917DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100918DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100919DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200920DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Allocated
921DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
922DMM Subscr_Conn(50462976){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100923DMM LOCATION UPDATING REQUEST: MI(TMSI)=50462976 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100924DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100925DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: Allocated
926DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: is child of Subscr_Conn(50462976)
927DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
928DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
929DREF VLR subscr MSISDN:46071 usage increases to: 2
930DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200931DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100932DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
933DVLR vlr_lu_fsm(50462976){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
934DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Allocated
935DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(50462976)
936DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
937DVLR VLR_Authenticate(50462976){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100938DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=3 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100939- sending GSM Auth Request for MSISDN:46071: tuple use_count=1 key_seq=3 auth_types=0x1 and...
940- ...rand=fa8f20b781b5881329d4fea26b1a3c51
941- ...expecting sres=5afc8d72
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200942DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100943DREF MSISDN:46071: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100944 auth_request_sent == 1
945 lu_result_sent == 0
946- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100947 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100948DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100949DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100950DMM MSISDN:46071: MM GSM AUTHENTICATION RESPONSE (sres = 5afc8d72)
951DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100952DVLR SUBSCR(MSISDN:46071) AUTH on GERAN received SRES/RES: 5afc8d72 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100953DVLR SUBSCR(MSISDN:46071) AUTH established GSM security context
954DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
955DVLR VLR_Authenticate(50462976){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
956DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
957DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(50462976)
958DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
959DVLR VLR_Authenticate(50462976){VLR_SUB_AS_AUTHENTICATED}: Deallocated
960DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
961DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
962DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
963DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
964DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
965DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: Allocated
966DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(50462976)
967DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
968DVLR GSUP tx: 04010809710000004026f0
969GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
970DVLR 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 +0200971DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100972DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100973 lu_result_sent == 0
974- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
975<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
976DVLR GSUP rx 17: 10010809710000004026f00804036470f1
977DREF VLR subscr MSISDN:46071 usage increases to: 3
978DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +0100979DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100980DVLR GSUP tx: 12010809710000004026f0
981GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
982DREF VLR subscr MSISDN:46071 usage decreases to: 2
983<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
984 lu_result_sent == 0
985- HLR also sends GSUP _UPDATE_LOCATION_RESULT
986<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
987DVLR GSUP rx 11: 06010809710000004026f0
988DREF VLR subscr MSISDN:46071 usage increases to: 3
989DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
990DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
991DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
992DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
993DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(50462976)
994DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Freeing instance
995DVLR upd_hlr_vlr_fsm(50462976){UPD_HLR_VLR_S_DONE}: Deallocated
996DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
997DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
998DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: Allocated
999DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(50462976)
1000DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1001DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1002DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: Allocated
1003DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(50462976)
1004DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1005DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1006DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1007DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(50462976)
1008DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Freeing instance
1009DVLR sub_pres_vlr_fsm(50462976){SUB_PRES_VLR_S_DONE}: Deallocated
1010DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1011DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1012DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1013- sending LU Accept for MSISDN:46071, with TMSI 0x07060504
1014DREF VLR subscr MSISDN:46071 usage decreases to: 2
1015<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1016- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1017 llist_count(&net->subscr_conns) == 1
1018 lu_result_sent == 1
1019msc_subscr_conn_is_accepted() == false
1020 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001021DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1022DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1023DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1024DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1025DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1026DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001027DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1028DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001029- even though the TMSI is not acked, we can already find the subscr with it
1030DREF VLR subscr MSISDN:46071 usage increases to: 3
1031 vsub != NULL == 1
1032 strcmp(vsub->imsi, imsi) == 0
1033 vsub->tmsi_new == 0x07060504
1034 vsub->tmsi == 0x03020100
1035DREF VLR subscr MSISDN:46071 usage decreases to: 2
1036- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001037 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001038DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001039DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001040DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
1041DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1042DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1043DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1044DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1045DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1046DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(50462976)
1047DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Freeing instance
1048DVLR lu_compl_vlr_fsm(50462976){LU_COMPL_VLR_S_DONE}: Deallocated
1049DVLR vlr_lu_fsm(50462976){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001050DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1051DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1052DMM Subscr_Conn(50462976){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1053DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1054DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
1055DMM Subscr_Conn(50462976){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1056DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001057DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1058DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(50462976)
1059DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1060DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Freeing instance
1061DVLR vlr_lu_fsm(50462976){VLR_ULA_S_DONE}: Deallocated
1062DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001063- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001064DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001065DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Freeing instance
1066DMM Subscr_Conn(50462976){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001067DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001068DRLL subscr MSISDN:46071: Freeing subscriber connection
1069DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001070 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001071- LU was successful, and the conn has already been closed
1072 llist_count(&net->subscr_conns) == 0
1073- subscriber has the new TMSI
1074DREF VLR subscr MSISDN:46071 usage increases to: 2
1075 vsub != NULL == 1
1076 strcmp(vsub->imsi, imsi) == 0
1077 vsub->tmsi_new == 0xffffffff
1078 vsub->tmsi == 0x07060504
1079DREF VLR subscr MSISDN:46071 usage decreases to: 1
1080---
1081- subscriber detaches, using new TMSI
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001082 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001083 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001084DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001085DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001086DMM IMSI DETACH INDICATION: MI(TMSI)=117835012
1087DREF VLR subscr MSISDN:46071 usage increases to: 2
1088DMM IMSI DETACH for MSISDN:46071
1089DREF VLR subscr MSISDN:46071 usage decreases to: 1
1090DREF VLR subscr MSISDN:46071 usage decreases to: 0
1091DREF freeing VLR subscr MSISDN:46071
1092DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001093- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001094DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001095DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001096 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001097 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001098===== test_gsm_authen_tmsi: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001099
1100full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte23466192018-02-14 00:19:06 +01001101talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001102
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001103===== test_gsm_authen_imei
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001104- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001105 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001106 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001107DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001108DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001109DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001110DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1111DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1112DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001113DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001114DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001115DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1116DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1117DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
1118DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1119DREF VLR subscr unknown usage increases to: 1
1120DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1121DVLR New subscr, IMSI: 901700000004620
1122DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001123DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001124DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1125DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1126DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1127DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1128DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1129DVLR GSUP tx: 08010809710000004026f0
1130GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1131DVLR 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 +02001132DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001133DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001134 lu_result_sent == 0
1135- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1136<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1137DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1138DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1139DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1140DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1141DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001142DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001143- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1144- ...rand=585df1ae287f6e273dce07090d61320b
1145- ...expecting sres=2d8b2c3e
1146DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1147<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1148 auth_request_sent == 1
1149 lu_result_sent == 0
1150- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
1151<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1152DVLR GSUP rx 11: 06010809710000004026f0
1153DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1154DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
1155DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
1156DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1157<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1158msc_subscr_conn_is_accepted() == false
1159 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001160DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1161DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1162DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1163DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1164DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1165DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001166DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1167DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001168 lu_result_sent == 0
1169- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001170 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001171DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001172DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001173DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1174DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001175DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001176DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1177DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1178DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1179DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1180DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1181DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1182DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1183DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1184DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1185DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1186DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1187DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1188DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1189DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1190DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1191DVLR GSUP tx: 04010809710000004026f0
1192GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1193DVLR 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 +02001194DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001195DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001196 lu_result_sent == 0
1197- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1198<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1199DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1200DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1201DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001202DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001203DVLR GSUP tx: 12010809710000004026f0
1204GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1205DREF VLR subscr MSISDN:46071 usage decreases to: 1
1206<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1207 lu_result_sent == 0
1208- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1209<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1210DVLR GSUP rx 11: 06010809710000004026f0
1211DREF VLR subscr MSISDN:46071 usage increases to: 2
1212DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1213DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1214DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1215DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1216DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1217DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1218DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1219DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1220DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1221DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1222DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1223DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1224DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1225DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1226DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1227DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1228DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1229DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1230DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1231DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1232DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1233DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1234DVLR 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 +02001235DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001236- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001237- DTAP matches expected message
1238DREF VLR subscr MSISDN:46071 usage decreases to: 1
1239<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1240- We will only do business when the IMEI is known
1241 llist_count(&net->subscr_conns) == 1
1242DREF VLR subscr MSISDN:46071 usage increases to: 2
1243 vsub->imei[0] == 0
1244DREF VLR subscr MSISDN:46071 usage decreases to: 1
1245msc_subscr_conn_is_accepted() == false
1246 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001247DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1248DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1249DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1250DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1251DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1252DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001253DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1254DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001255- MS replies with an Identity Response
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001256 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001257DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001258DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001259DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
1260DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001261DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1262DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1263- sending LU Accept for MSISDN:46071
1264DREF VLR subscr MSISDN:46071 usage increases to: 2
1265DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI}: state_chg to LU_COMPL_VLR_S_DONE
1266DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1267DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1268DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1269DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1270DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1271DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001272DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1273DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1274DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1275DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1276DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
1277DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1278DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001279DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1280DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1281DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1282DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1283DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1284DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001285- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001286DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001287DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1288DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001289DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001290DRLL subscr MSISDN:46071: Freeing subscriber connection
1291DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001292 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001293- LU was successful, and the conn has already been closed
1294 lu_result_sent == 1
1295 llist_count(&net->subscr_conns) == 0
1296- Subscriber has the IMEI
1297DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001298 strcmp(vsub->imei, "423423423423420") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001299DREF VLR subscr MSISDN:46071 usage decreases to: 1
1300---
1301- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001302 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001303 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001304DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001305DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001306DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
1307DREF VLR subscr MSISDN:46071 usage increases to: 2
1308DMM IMSI DETACH for MSISDN:46071
1309DREF VLR subscr MSISDN:46071 usage decreases to: 1
1310DREF VLR subscr MSISDN:46071 usage decreases to: 0
1311DREF freeing VLR subscr MSISDN:46071
1312DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001313- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001314DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001315DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001316 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001317 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001318===== test_gsm_authen_imei: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001319
1320full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte23466192018-02-14 00:19:06 +01001321talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001322
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001323===== test_gsm_authen_tmsi_imei
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001324- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001325 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001326 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001327DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001328DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001329DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001330DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
1331DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1332DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001333DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001334DMM LU/new-LAC: 1/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001335DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
1336DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
1337DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
1338DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1339DREF VLR subscr unknown usage increases to: 1
1340DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
1341DVLR New subscr, IMSI: 901700000004620
1342DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001343DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001344DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1345DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1346DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1347DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
1348DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1349DVLR GSUP tx: 08010809710000004026f0
1350GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
1351DVLR 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 +02001352DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001353DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001354 lu_result_sent == 0
1355- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1356<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1357DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
1358DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1359DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1360DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
1361DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001362DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001363- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
1364- ...rand=585df1ae287f6e273dce07090d61320b
1365- ...expecting sres=2d8b2c3e
1366DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1367<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1368 auth_request_sent == 1
1369 lu_result_sent == 0
1370- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
1371<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1372DVLR GSUP rx 11: 06010809710000004026f0
1373DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1374DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
1375DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
1376DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
1377<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1378msc_subscr_conn_is_accepted() == false
1379 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001380DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1381DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1382DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1383DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
1384DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1385DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001386DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1387DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001388 lu_result_sent == 0
1389- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001390 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001391DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001392DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001393DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e)
1394DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001395DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001396DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context
1397DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1398DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1399DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1400DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000004620)
1401DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1402DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1403DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1404DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1405DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1406DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1407DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1408DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
1409DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1410DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1411DVLR GSUP tx: 04010809710000004026f0
1412GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
1413DVLR 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 +02001414DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001415DREF IMSI:901700000004620: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001416 lu_result_sent == 0
1417- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1418<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
1419DVLR GSUP rx 17: 10010809710000004026f00804036470f1
1420DREF VLR subscr IMSI:901700000004620 usage increases to: 2
1421DVLR IMSI:901700000004620 has MSISDN:46071
Maxa263bb22017-12-27 13:23:44 +01001422DVLR SUBSCR(MSISDN:46071) VLR: update for IMSI=901700000004620 (MSISDN=46071, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001423DVLR GSUP tx: 12010809710000004026f0
1424GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
1425DREF VLR subscr MSISDN:46071 usage decreases to: 1
1426<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1427 lu_result_sent == 0
1428- HLR also sends GSUP _UPDATE_LOCATION_RESULT, and we send an ID Request for the IMEI to the MS
1429<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
1430DVLR GSUP rx 11: 06010809710000004026f0
1431DREF VLR subscr MSISDN:46071 usage increases to: 2
1432DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1433DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1434DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1435DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1436DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1437DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
1438DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
1439DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1440DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1441DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
1442DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
1443DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1444DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1445DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
1446DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
1447DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1448DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1449DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1450DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
1451DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
1452DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
1453DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1454DVLR 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 +02001455DMSC msc_tx 3 bytes to MSISDN:46071 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001456- DTAP --RAN_GERAN_A--> MS: GSM48_MT_MM_ID_REQ: 051802
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001457- DTAP matches expected message
1458DREF VLR subscr MSISDN:46071 usage decreases to: 1
1459<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1460- We will only do business when the IMEI is known
1461 llist_count(&net->subscr_conns) == 1
1462DREF VLR subscr MSISDN:46071 usage increases to: 2
1463 vsub->imei[0] == 0
1464DREF VLR subscr MSISDN:46071 usage decreases to: 1
1465msc_subscr_conn_is_accepted() == false
1466 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001467DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1468DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1469DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1470DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1471DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1472DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001473DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1474DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001475- MS replies with an Identity Response
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001476 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_ID_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001477DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001478DRLL Dispatching 04.08 message GSM48_MT_MM_ID_RESP (0x5:0x19)
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001479DMM IDENTITY RESPONSE: MI(IMEI)=423423423423420
1480DVLR set IMEI on subscriber; IMSI=901700000004620 IMEI=423423423423420
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001481DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_ID_IMEI
1482DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: Received Event LU_COMPL_VLR_E_IMEI_CHECK_ACK
1483DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: lu_compl_vlr_new_tmsi()
1484DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_IMEI_TMSI}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1485- sending LU Accept for MSISDN:46071, with TMSI 0x03020100
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001486DMM MSISDN:46071: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001487DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001488- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1489 llist_count(&net->subscr_conns) == 1
1490 lu_result_sent == 1
1491msc_subscr_conn_is_accepted() == false
1492 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001493DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1494DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1495DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1496DRLL subscr MSISDN:46071: Message not permitted for initial conn: unknown 0x33
1497DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1498DRLL subscr MSISDN:46071: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001499DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1500DRLL subscr MSISDN:46071: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001501- even though the TMSI is not acked, we can already find the subscr with it
1502DREF VLR subscr MSISDN:46071 usage increases to: 2
1503 vsub != NULL == 1
1504 strcmp(vsub->imsi, imsi) == 0
1505 vsub->tmsi_new == 0x03020100
1506 vsub->tmsi == 0xffffffff
1507DREF VLR subscr MSISDN:46071 usage decreases to: 1
1508- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001509 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001510DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001511DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001512DMM TMSI Reallocation Completed. Subscriber: MSISDN:46071
1513DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1514DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1515DREF VLR subscr MSISDN:46071 usage increases to: 2
1516DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1517DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1518DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1519DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
1520DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
1521DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
1522DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001523DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1524DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1525DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1526DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1527DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
1528DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1529DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001530DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1531DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
1532DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1533DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
1534DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
1535DMM msc_subscr_conn_close(vsub=MSISDN:46071, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001536- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001537DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001538DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
1539DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001540DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001541DRLL subscr MSISDN:46071: Freeing subscriber connection
1542DREF VLR subscr MSISDN:46071 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001543 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001544- LU was successful, and the conn has already been closed
1545 llist_count(&net->subscr_conns) == 0
1546- Subscriber has the IMEI and TMSI
1547DREF VLR subscr MSISDN:46071 usage increases to: 2
Neels Hofmeyr34d33bd2017-07-20 02:56:21 +02001548 strcmp(vsub->imei, "423423423423420") == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001549 vsub->tmsi == 0x03020100
1550DREF VLR subscr MSISDN:46071 usage decreases to: 1
1551---
1552- subscriber detaches, using TMSI
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001553 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001554 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001555DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001556DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001557DMM IMSI DETACH INDICATION: MI(TMSI)=50462976
1558DREF VLR subscr MSISDN:46071 usage increases to: 2
1559DMM IMSI DETACH for MSISDN:46071
1560DREF VLR subscr MSISDN:46071 usage decreases to: 1
1561DREF VLR subscr MSISDN:46071 usage decreases to: 0
1562DREF freeing VLR subscr MSISDN:46071
1563DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001564- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001565DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001566DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001567 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001568 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001569===== test_gsm_authen_tmsi_imei: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001570
1571full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte23466192018-02-14 00:19:06 +01001572talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001573
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001574===== test_gsm_milenage_authen
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001575- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001576 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001577 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001578DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001579DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001580DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001581DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1582DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1583DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001584DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001585DMM LU/new-LAC: 0/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001586DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1587DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1588DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
1589DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1590DREF VLR subscr unknown usage increases to: 1
1591DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1592DVLR New subscr, IMSI: 901700000010650
1593DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001594DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001595DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1596DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1597DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1598DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1599DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1600DVLR GSUP tx: 08010809710000000156f0
1601GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1602DVLR 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 +02001603DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001604DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001605 lu_result_sent == 0
1606- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1607<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c
1608DVLR GSUP rx 311: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c
1609DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1610DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1611DVLR SUBSCR(IMSI:901700000010650) Received 3 auth tuples
1612DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001613DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001614- sending GSM Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1615- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1616- ...expecting sres=9b36efdf
1617DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1618<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1619 auth_request_sent == 1
1620 lu_result_sent == 0
1621- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001622 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001623DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001624DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001625DMM IMSI:901700000010650: MM GSM AUTHENTICATION RESPONSE (sres = 9b36efdf)
1626DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001627DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: 9b36efdf (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001628DVLR SUBSCR(IMSI:901700000010650) AUTH established GSM security context
1629DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1630DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1631DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1632DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
1633DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1634DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1635DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1636DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1637DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1638DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1639DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1640DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1641DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1642DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1643DVLR GSUP tx: 04010809710000000156f0
1644GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
1645DVLR 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 +02001646DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001647DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001648 lu_result_sent == 0
1649- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1650<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1651DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1652DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1653DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +01001654DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001655DVLR GSUP tx: 12010809710000000156f0
1656GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1657DREF VLR subscr MSISDN:42342 usage decreases to: 1
1658<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1659 lu_result_sent == 0
1660- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1661<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1662DVLR GSUP rx 11: 06010809710000000156f0
1663DREF VLR subscr MSISDN:42342 usage increases to: 2
1664DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1665DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1666DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1667DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1668DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1669DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1670DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1671DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1672DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1673DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1674DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1675DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1676DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1677DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1678DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
1679DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1680DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1681DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1682DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
1683DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1684DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1685DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1686- sending LU Accept for MSISDN:42342
1687DREF VLR subscr MSISDN:42342 usage increases to: 3
1688DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
1689DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1690DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1691DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1692DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1693DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1694DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001695DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1696DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1697DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1698DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1699DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
1700DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1701DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001702DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1703DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1704DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1705DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1706DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1707DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001708- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001709DREF MSISDN:42342: MSC conn use - fsm == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001710DRLL subscr MSISDN:42342: Freeing subscriber connection
1711DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001712DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1713DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001714DREF VLR subscr MSISDN:42342 usage decreases to: 1
1715<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
Philipp Maierfbf66102017-04-09 12:32:51 +02001716 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001717- LU was successful, and the conn has already been closed
1718 lu_result_sent == 1
1719 llist_count(&net->subscr_conns) == 0
1720---
1721- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001722 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001723 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001724DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001725DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001726DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001727DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001728DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1729DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1730DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001731DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
1732DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
1733DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
1734DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1735DREF VLR subscr MSISDN:42342 usage increases to: 2
1736DREF VLR subscr MSISDN:42342 usage increases to: 3
1737DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1738DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1739DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1740DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
1741DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1742DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001743DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001744- sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
1745- ...rand=c187a53a5e6b9d573cac7c74451fd46d
1746- ...expecting sres=85aa3130
1747DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001748DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001749DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001750 cm_service_result_sent == 0
1751 auth_request_sent == 1
1752- needs auth, not yet accepted
1753msc_subscr_conn_is_accepted() == false
1754 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001755DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1756DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1757DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1758DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
1759DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1760DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001761DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1762DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001763- MS sends Authen Response, VLR accepts with a CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001764 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001765DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001766DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001767DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 85aa3130)
1768DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001769DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 85aa3130 (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001770DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
1771DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1772DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1773DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1774DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
1775DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1776DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1777DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
1778DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
1779DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1780DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
1781DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
1782DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
1783DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
1784DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
1785DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1786DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
1787DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1788- sending CM Service Accept for MSISDN:42342
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001789DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1790DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
1791DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1792DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
1793DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1794DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
1795DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1796DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001797DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001798 cm_service_result_sent == 1
1799- a USSD request is serviced
1800 expecting USSD:
1801 Your extension is 42342
Harald Welte80315ef2018-01-24 22:53:00 +01001802 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001803DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +01001804DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
1805DMM MSISDN:42342: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001806DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1807DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001808DMM USSD: Own number requested
1809DMM MSISDN:42342: MSISDN = 42342
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001810DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001811- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001812- DTAP matches expected message
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001813DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
1814DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
1815DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1816DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001817DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1818DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1819DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
1820DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
1821DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001822- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001823DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001824DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1825DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001826DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001827DRLL subscr MSISDN:42342: Freeing subscriber connection
1828DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001829 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001830- all requests serviced, conn has been released
1831 llist_count(&net->subscr_conns) == 0
1832---
1833- an SMS is sent, MS is paged
1834DREF VLR subscr MSISDN:42342 usage increases to: 2
1835 llist_count(&vsub->cs.requests) == 0
1836DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001837DMM Subscriber MSISDN:42342 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001838 RAN_GERAN_A sends out paging request to IMSI 901700000010650, TMSI 0xffffffff, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001839 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001840DREF VLR subscr MSISDN:42342 usage increases to: 4
1841 llist_count(&vsub->cs.requests) == 1
1842DREF VLR subscr MSISDN:42342 usage decreases to: 3
1843 paging_sent == 1
1844 paging_stopped == 0
1845- the subscriber and its pending request should remain
1846DREF VLR subscr MSISDN:42342 usage increases to: 4
1847 llist_count(&vsub->cs.requests) == 1
1848DREF VLR subscr MSISDN:42342 usage decreases to: 3
1849- MS replies with Paging Response, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001850 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001851 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001852DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001853DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001854DRR PAGING RESPONSE: MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001855DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001856DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1857DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1858DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001859DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
1860DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
1861DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=GSM net=GERAN Auth (no Ciph)
1862DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1863DREF VLR subscr MSISDN:42342 usage increases to: 4
1864DREF VLR subscr MSISDN:42342 usage increases to: 5
1865DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1866DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1867DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1868DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
1869DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1870DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001871DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001872- sending GSM Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
1873- ...rand=efa9c29a9742148d5c9070348716e1bb
1874- ...expecting sres=69d5f9fb
1875DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001876DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001877DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001878 auth_request_sent == 1
1879- needs auth, not yet accepted
1880msc_subscr_conn_is_accepted() == false
1881 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001882DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1883DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1884DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1885DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
1886DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1887DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001888DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1889DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001890- MS sends Authen Response, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001891 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001892DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001893DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001894DMM MSISDN:42342: MM GSM AUTHENTICATION RESPONSE (sres = 69d5f9fb)
1895DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001896DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 69d5f9fb (4 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001897DVLR SUBSCR(MSISDN:42342) AUTH established GSM security context
1898DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1899DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1900DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1901DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
1902DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1903DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1904DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
1905DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
1906DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1907DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
1908DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
1909DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
1910DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
1911DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
1912DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1913DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
1914DVLR 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 +02001915DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1916DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
1917DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1918DPAG Paging success for MSISDN:42342 (event=0)
1919DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +01001920DCC (ti 00 sub MSISDN:42342 callref 40000003) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001921DREF VLR subscr MSISDN:42342 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001922DREF MSISDN:42342: MSC conn use + trans_sms == 3 (0x16)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001923DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001924- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001925- DTAP matches expected message
1926DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001927DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
Harald Welte80315ef2018-01-24 22:53:00 +01001928DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: SMS
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001929DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
Harald Welte80315ef2018-01-24 22:53:00 +01001930DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001931DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001932 dtap_tx_confirmed == 1
1933 paging_stopped == 1
1934- SMS was delivered, no requests pending for subscr
1935DREF VLR subscr MSISDN:42342 usage increases to: 5
1936 llist_count(&vsub->cs.requests) == 0
1937DREF VLR subscr MSISDN:42342 usage decreases to: 4
1938- conn is still open to wait for SMS ack dance
1939 llist_count(&net->subscr_conns) == 1
1940- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +01001941 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001942DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +01001943DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001944DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1945DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
1946DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
Harald Welte80315ef2018-01-24 22:53:00 +01001947DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001948DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001949 llist_count(&net->subscr_conns) == 1
1950- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +01001951 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001952DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +01001953DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001954DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
1955DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +01001956- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001957- DTAP matches expected message
1958DREF VLR subscr MSISDN:42342 usage decreases to: 3
1959DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001960DREF MSISDN:42342: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001961DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
1962DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
1963DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1964DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001965DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1966DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1967DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
1968DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
1969DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001970- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001971DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001972DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1973DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001974DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001975DRLL subscr MSISDN:42342: Freeing subscriber connection
1976DREF VLR subscr MSISDN:42342 usage decreases to: 1
1977 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001978 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001979- SMS is done, conn is gone
1980 llist_count(&net->subscr_conns) == 0
1981---
1982- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001983 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001984 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001985DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001986DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001987DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
1988DREF VLR subscr MSISDN:42342 usage increases to: 2
1989DMM IMSI DETACH for MSISDN:42342
1990DREF VLR subscr MSISDN:42342 usage decreases to: 1
1991DREF VLR subscr MSISDN:42342 usage decreases to: 0
1992DREF freeing VLR subscr MSISDN:42342
1993DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001994- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001995DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001996DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +02001997 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001998 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001999===== test_gsm_milenage_authen: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002000
2001full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte23466192018-02-14 00:19:06 +01002002talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002003
Neels Hofmeyr8e0af0b2018-03-10 03:32:18 +01002004===== test_wrong_sres_length
2005- Total time passed: 0.000000 s
2006- Location Update request causes a GSUP Send Auth Info request to HLR
2007 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
2008 new conn
2009DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
2010DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
2011DREF unknown: MSC conn use + fsm == 2 (0x5)
2012DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
2013DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
2014DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
2015DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
2016DMM LU/new-LAC: 1/23
2017DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
2018DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
2019DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth (no Ciph)
2020DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
2021DREF VLR subscr unknown usage increases to: 1
2022DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
2023DVLR New subscr, IMSI: 901700000004620
2024DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2025DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2026DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
2027DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
2028DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated
2029DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000004620)
2030DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
2031DVLR GSUP tx: 08010809710000004026f0
2032GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0
2033DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
2034DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
2035DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
2036 lu_result_sent == 0
2037- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
2038<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
2039DVLR GSUP rx 191: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a8000322201012aca96fb4ffdea5c985cbafa9b6e18b210420bde240220807fa7502e07e1c0003222010e7c03ba7cf0e2fde82b2dc4d63077d422104a29514ae2208e2b234f80788640003222010fa8f20b781b5881329d4fea26b1a3c5121045afc8d7222082392f14f709ae000032220100fd4cc8dbe8715d1f439e304edfd68dc2104bc8d1c5b2208da7cdd6bfe2d7000
2040DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2041DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
2042DVLR SUBSCR(IMSI:901700000004620) Received 5 auth tuples
2043DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01002044DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1)
Neels Hofmeyr8e0af0b2018-03-10 03:32:18 +01002045- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and...
2046- ...rand=585df1ae287f6e273dce07090d61320b
2047- ...expecting sres=2d8b2c3e
2048DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2049<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
2050 auth_request_sent == 1
2051 lu_result_sent == 0
2052- If the HLR were to send a GSUP _UPDATE_LOCATION_RESULT we'd still reject
2053<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
2054DVLR GSUP rx 11: 06010809710000004026f0
2055DREF VLR subscr IMSI:901700000004620 usage increases to: 2
2056DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_HLR_LU_RES
2057DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Event VLR_ULA_E_HLR_LU_RES not permitted
2058DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
2059<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
2060msc_subscr_conn_is_accepted() == false
2061 requests shall be thwarted
2062DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
2063DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_CC_SETUP
2064DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
2065DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: unknown 0x33
2066DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
2067DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
2068DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
2069DRLL subscr IMSI:901700000004620: Message not permitted for initial conn: SMS:0x01
2070 lu_result_sent == 0
2071- MS sends Authen Response with too short SRES data, auth is thwarted.
2072 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
2073DREF IMSI:901700000004620: MSC conn use + dtap == 2 (0x6)
2074DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
2075DMM IMSI:901700000004620: MM AUTHENTICATION RESPONSE: l3 length invalid: 5
2076DMM IMSI:901700000004620: MM AUTHENTICATION RESPONSE: invalid: parsing GSM AKA Auth Response failed with rc=-22; dispatching zero length SRES/RES to trigger failure
2077DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = )
2078DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01002079DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: (0 bytes)
Neels Hofmeyr11d2ce32018-03-10 00:25:20 +01002080DVLR SUBSCR(IMSI:901700000004620) AUTH SRES/RES missing
Neels Hofmeyr8e0af0b2018-03-10 03:32:18 +01002081DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_AUTH_FAILED
2082DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTH_FAILED
2083DVLR GSUP tx: 0b010809710000004026f0
2084GSUP --> HLR: OSMO_GSUP_MSGT_AUTH_FAIL_REPORT: 0b010809710000004026f0
2085DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTH_FAILED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2086DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTH_FAILED}: Removing from parent vlr_lu_fsm(901700000004620)
2087DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTH_FAILED}: Freeing instance
2088DVLR VLR_Authenticate(901700000004620){VLR_SUB_AS_AUTH_FAILED}: Deallocated
2089DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
2090- sending LU Reject for IMSI:901700000004620, cause 3
2091DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
2092DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
2093DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
2094DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Close event, cause 1
2095DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
2096DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
2097DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
2098DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
2099DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
2100DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
2101DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
2102DMM msc_subscr_conn_close(vsub=IMSI:901700000004620, cause=2): no conn fsm, releasing directly without release event.
2103- BSSAP Clear --RAN_GERAN_A--> MS
2104DREF IMSI:901700000004620: MSC conn use - fsm == 1 (0x2)
2105DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
2106DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
2107DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0)
2108DRLL subscr IMSI:901700000004620: Freeing subscriber connection
2109DREF VLR subscr IMSI:901700000004620 usage decreases to: 0
2110DREF freeing VLR subscr IMSI:901700000004620
2111 lu_result_sent == 2
2112 llist_count(&net->subscr_conns) == 0
2113===== test_wrong_sres_length: SUCCESS
2114
2115full talloc report on 'msgb' (total 0 bytes in 1 blocks)
2116talloc_total_blocks(tall_bsc_ctx) == 7
2117
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002118full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte23466192018-02-14 00:19:06 +01002119talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01002120