blob: fa820f72c2ddb484d2907f665e198f73c4df1e25 [file] [log] [blame]
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001===== test_umts_authen_geran
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(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
9DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
10DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010011DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +010012DMM LU/new-LAC: 0/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010013DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
14DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
15DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth (no Ciph)
16DVLR vlr_lu_fsm(901700000010650){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=901700000010650 id=901700000010650
19DVLR New subscr, IMSI: 901700000010650
20DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +020021DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010022DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
23DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
24DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
25DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
26DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
27DVLR GSUP tx: 08010809710000000156f0
28GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
29DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +010030DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +010031DREF IMSI:901700000010650: 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: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
35DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
36DREF VLR subscr IMSI:901700000010650 usage increases to: 2
37DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
38DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
39DVLR 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 +010040DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010041- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
42- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
43- ...autn=8704f5ba55f30000d2ee44b22c8ea919
44- ...expecting res=e229c19e791f2e41
45DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
46<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
47 auth_request_sent == 1
48 lu_result_sent == 0
49- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +010050 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +010051DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +010052DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +010053DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010054DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +010055DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: e229c19e791f2e41 (8 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010056DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
57DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
58DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
59DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
60DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
61DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
62DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
63DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
64DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
65DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
66DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
67DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
68DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
69DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
70DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
71DVLR GSUP tx: 04010809710000000156f0
72GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
73DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +010074DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +010075DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +020076 gsup_tx_confirmed == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010077 lu_result_sent == 0
78- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
79<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
80DVLR GSUP rx 17: 10010809710000000156f00804032443f2
81DREF VLR subscr IMSI:901700000010650 usage increases to: 2
82DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +010083DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +010084DVLR GSUP tx: 12010809710000000156f0
85GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
86DREF VLR subscr MSISDN:42342 usage decreases to: 1
87<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
88 lu_result_sent == 0
89- HLR also sends GSUP _UPDATE_LOCATION_RESULT
90<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
91DVLR GSUP rx 11: 06010809710000000156f0
92DREF VLR subscr MSISDN:42342 usage increases to: 2
93DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
94DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
95DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
96DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
97DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
98DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
99DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
100DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
101DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
102DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
103DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
104DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
105DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
106DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
107DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
108DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
109DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
110DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
111DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
112DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
113DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
114DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200115DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
116DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
117- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
118DREF VLR subscr MSISDN:42342 usage decreases to: 1
119<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
120 lu_result_sent == 1
121- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
122 llist_count(&net->subscr_conns) == 1
123msc_subscr_conn_is_accepted() == false
124 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100125DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
126DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
127DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
128DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
129DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
130DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100131DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
132DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200133- even though the TMSI is not acked, we can already find the subscr with it
134DREF VLR subscr MSISDN:42342 usage increases to: 2
135 vsub != NULL == 1
136 strcmp(vsub->imsi, imsi) == 0
137 vsub->tmsi_new == 0x03020100
138 vsub->tmsi == 0xffffffff
139DREF VLR subscr MSISDN:42342 usage decreases to: 1
140- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100141 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100142DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100143DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200144DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
145DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
146DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
147DREF VLR subscr MSISDN:42342 usage increases to: 2
148DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100149DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
150DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
151DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
152DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
153DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
154DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200155DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
156DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
157DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100158DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
159DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200160DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
161DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100162DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
163DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
164DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
165DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
166DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
167DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200168- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100169DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200170DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
171DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100172DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100173DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100174DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200175 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100176- LU was successful, and the conn has already been closed
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100177 llist_count(&net->subscr_conns) == 0
178---
179- 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 +0100180 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100181 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100182DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100183DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100184DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100185DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200186DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
187DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
188DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100189DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
190DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
191DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth (no Ciph)
192DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
193DREF VLR subscr MSISDN:42342 usage increases to: 2
194DREF VLR subscr MSISDN:42342 usage increases to: 3
195DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
196DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
197DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
198DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
199DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
200DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100201DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100202- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
203- ...rand=c187a53a5e6b9d573cac7c74451fd46d
204- ...autn=1843a645b98d00005b2d666af46c45d9
205- ...expecting res=7db47cf7f81e4dc7
206DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100207DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100208DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100209 cm_service_result_sent == 0
210 auth_request_sent == 1
211- needs auth, not yet accepted
212msc_subscr_conn_is_accepted() == false
213 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100214DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
215DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
216DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
217DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
218DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
219DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100220DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
221DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100222- MS sends Authen Response, VLR accepts with a CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100223 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100224DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100225DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100226DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100227DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100228DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 7db47cf7f81e4dc7 (8 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100229DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
230DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
231DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
232DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
233DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
234DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
235DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
236DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
237DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
238DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
239DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
240DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
241DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
242DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
243DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
244DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
245DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
246DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
247- sending CM Service Accept for MSISDN:42342
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200248DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
249DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
250DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
251DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100252DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
253DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
254DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
255DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100256DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100257 cm_service_result_sent == 1
258- a USSD request is serviced
259 expecting USSD:
260 Your extension is 42342
Harald Welte80315ef2018-01-24 22:53:00 +0100261 MSC <--RAN_GERAN_A-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100262DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +0100263DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
264DMM MSISDN:42342: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200265DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
266DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100267DMM USSD: Own number requested
268DMM MSISDN:42342: MSISDN = 42342
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200269DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100270- DTAP --RAN_GERAN_A--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100271- DTAP matches expected message
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100272DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
273DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200274DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
275DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100276DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
277DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
278DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
279DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
280DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200281- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100282DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200283DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
284DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100285DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100286DRLL subscr MSISDN:42342: Freeing subscriber connection
287DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200288 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100289- all requests serviced, conn has been released
290 llist_count(&net->subscr_conns) == 0
291---
292- an SMS is sent, MS is paged
293DREF VLR subscr MSISDN:42342 usage increases to: 2
294 llist_count(&vsub->cs.requests) == 0
295DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200296DMM Subscriber MSISDN:42342 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100297 RAN_GERAN_A sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200298 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100299DREF VLR subscr MSISDN:42342 usage increases to: 4
300 llist_count(&vsub->cs.requests) == 1
301DREF VLR subscr MSISDN:42342 usage decreases to: 3
302 paging_sent == 1
303 paging_stopped == 0
304- the subscriber and its pending request should remain
305DREF VLR subscr MSISDN:42342 usage increases to: 4
306 llist_count(&vsub->cs.requests) == 1
307DREF VLR subscr MSISDN:42342 usage decreases to: 3
308- MS replies with Paging Response, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100309 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100310 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100311DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100312DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100313DRR PAGING RESPONSE: MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100314DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200315DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
316DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
317DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100318DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
319DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
320DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth (no Ciph)
321DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
322DREF VLR subscr MSISDN:42342 usage increases to: 4
323DREF VLR subscr MSISDN:42342 usage increases to: 5
324DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
325DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
326DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
327DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
328DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
329DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100330DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100331- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
332- ...rand=efa9c29a9742148d5c9070348716e1bb
333- ...autn=f9375e6d41e1000096e7fe4ff1c27e39
334- ...expecting res=706f996719ba609c
335DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100336DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100337DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100338 auth_request_sent == 1
339- needs auth, not yet accepted
340msc_subscr_conn_is_accepted() == false
341 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100342DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
343DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
344DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
345DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
346DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
347DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100348DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
349DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100350- MS sends Authen Response, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100351 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100352DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100353DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100354DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 706f996719ba609c)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100355DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100356DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 706f996719ba609c (8 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100357DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
358DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
359DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
360DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
361DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
362DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
363DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
364DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
365DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
366DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
367DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
368DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
369DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
370DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
371DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
372DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
373DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
374DVLR 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 +0200375DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
376DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
377DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
378DPAG Paging success for MSISDN:42342 (event=0)
379DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100380DCC (ti 00 sub MSISDN:42342 callref 40000001) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100381DREF VLR subscr MSISDN:42342 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100382DREF MSISDN:42342: MSC conn use + trans_sms == 3 (0x16)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200383DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100384- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100385- DTAP matches expected message
386DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100387DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
388DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
389DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
390DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100391DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100392 dtap_tx_confirmed == 1
393 paging_stopped == 1
394- SMS was delivered, no requests pending for subscr
395DREF VLR subscr MSISDN:42342 usage increases to: 5
396 llist_count(&vsub->cs.requests) == 0
397DREF VLR subscr MSISDN:42342 usage decreases to: 4
398- conn is still open to wait for SMS ack dance
399 llist_count(&net->subscr_conns) == 1
400- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100401 MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100402DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100403DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200404DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
405DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100406DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
407DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100408DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100409 llist_count(&net->subscr_conns) == 1
410- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100411 MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100412DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100413DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200414DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
415DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_GERAN_A
Harald Welte80315ef2018-01-24 22:53:00 +0100416- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100417- DTAP matches expected message
418DREF VLR subscr MSISDN:42342 usage decreases to: 3
419DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100420DREF MSISDN:42342: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100421DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
422DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200423DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
424DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100425DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
426DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
427DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
428DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
429DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200430- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100431DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200432DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
433DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100434DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100435DRLL subscr MSISDN:42342: Freeing subscriber connection
436DREF VLR subscr MSISDN:42342 usage decreases to: 1
437 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200438 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100439- SMS is done, conn is gone
440 llist_count(&net->subscr_conns) == 0
441---
442- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100443 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100444 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100445DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100446DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100447DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
448DREF VLR subscr MSISDN:42342 usage increases to: 2
449DMM IMSI DETACH for MSISDN:42342
450DREF VLR subscr MSISDN:42342 usage decreases to: 1
451DREF VLR subscr MSISDN:42342 usage decreases to: 0
452DREF freeing VLR subscr MSISDN:42342
453DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200454- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100455DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100456DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +0200457 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100458 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100459===== test_umts_authen_geran: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100460
461full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte23466192018-02-14 00:19:06 +0100462talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100463
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100464===== test_umts_authen_utran
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100465- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100466 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100467 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100468DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100469DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100470DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200471DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
472DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
473DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100474DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100475DMM LU/new-LAC: 0/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100476DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
477DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200478DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100479DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
480DREF VLR subscr unknown usage increases to: 1
481DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
482DVLR New subscr, IMSI: 901700000010650
483DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200484DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100485DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
486DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
487DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
488DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
489DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
490DVLR GSUP tx: 08010809710000000156f0
491GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
492DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100493DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100494DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100495 lu_result_sent == 0
496- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
497<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
498DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
499DREF VLR subscr IMSI:901700000010650 usage increases to: 2
500DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
501DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
502DVLR 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 +0100503DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100504- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
505- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
506- ...autn=8704f5ba55f30000d2ee44b22c8ea919
507- ...expecting res=e229c19e791f2e41
508DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
509<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
510 auth_request_sent == 1
511 lu_result_sent == 0
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200512- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100513 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100514DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100515DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100516DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100517DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100518DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100519DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
520DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
521DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
522DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
523DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
524DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
525DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
526DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
527DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +0100528DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100529DMM -> SECURITY MODE CONTROL IMSI:901700000010650
530- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
531- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200532DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100533DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100534DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100535 security_mode_ctrl_sent == 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200536 lu_result_sent == 0
537- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
538DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
539DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
540DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
541DIUCS IMSI:901700000010650: tx CommonID 901700000010650
542- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
543DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
544DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100545DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
546DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
547DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
548DVLR GSUP tx: 04010809710000000156f0
549GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
550DVLR 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 +0200551 gsup_tx_confirmed == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100552 lu_result_sent == 0
553- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
554<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
555DVLR GSUP rx 17: 10010809710000000156f00804032443f2
556DREF VLR subscr IMSI:901700000010650 usage increases to: 2
557DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +0100558DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100559DVLR GSUP tx: 12010809710000000156f0
560GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
561DREF VLR subscr MSISDN:42342 usage decreases to: 1
562<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
563 lu_result_sent == 0
564- HLR also sends GSUP _UPDATE_LOCATION_RESULT
565<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
566DVLR GSUP rx 11: 06010809710000000156f0
567DREF VLR subscr MSISDN:42342 usage increases to: 2
568DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
569DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
570DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
571DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
572DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
573DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
574DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
575DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
576DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
577DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
578DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
579DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
580DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
581DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
582DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
583DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
584DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
585DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
586DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
587DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
588DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
589DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200590DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
591DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
592- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
593DREF VLR subscr MSISDN:42342 usage decreases to: 1
594<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
595 lu_result_sent == 1
596- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
597 llist_count(&net->subscr_conns) == 1
598msc_subscr_conn_is_accepted() == false
599 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100600DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
601DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
602DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
603DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
604DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
605DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100606DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
607DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200608- even though the TMSI is not acked, we can already find the subscr with it
609DREF VLR subscr MSISDN:42342 usage increases to: 2
610 vsub != NULL == 1
611 strcmp(vsub->imsi, imsi) == 0
612 vsub->tmsi_new == 0x03020100
613 vsub->tmsi == 0xffffffff
614DREF VLR subscr MSISDN:42342 usage decreases to: 1
615- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100616 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100617DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100618DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200619DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
620DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
621DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
622DREF VLR subscr MSISDN:42342 usage increases to: 2
623DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100624DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
625DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
626DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
627DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
628DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
629DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200630DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
631DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
632DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100633DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
634DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200635DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
636DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100637DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
638DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
639DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
640DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
641DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
642DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200643- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100644DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200645DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
646DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100647DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100648DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100649DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200650 iu_release_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100651- LU was successful, and the conn has already been closed
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100652 llist_count(&net->subscr_conns) == 0
653---
654- 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 +0100655 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100656 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100657DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100658DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100659DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100660DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200661DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
662DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
663DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100664DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
665DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200666DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100667DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
668DREF VLR subscr MSISDN:42342 usage increases to: 2
669DREF VLR subscr MSISDN:42342 usage increases to: 3
670DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
671DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
672DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
673DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
674DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
675DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100676DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100677- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
678- ...rand=c187a53a5e6b9d573cac7c74451fd46d
679- ...autn=1843a645b98d00005b2d666af46c45d9
680- ...expecting res=7db47cf7f81e4dc7
681DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100682DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100683DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100684 cm_service_result_sent == 0
685 auth_request_sent == 1
686- needs auth, not yet accepted
687msc_subscr_conn_is_accepted() == false
688 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100689DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
690DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
691DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
692DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
693DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
694DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100695DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
696DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200697- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100698 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100699DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100700DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100701DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100702DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100703DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100704DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
705DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
706DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
707DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
708DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
709DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
710DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
711DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
712DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
713DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100714DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100715DMM -> SECURITY MODE CONTROL MSISDN:42342
716- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
717- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200718DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100719DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100720DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100721 security_mode_ctrl_sent == 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200722 cm_service_result_sent == 0
723- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
724DMM <- SECURITY MODE COMPLETE MSISDN:42342
725DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
726DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
727DIUCS MSISDN:42342: tx CommonID 901700000010650
728- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
729DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
730DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
731DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
732DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
733DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
734DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
735DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
736DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
737DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
738DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
739DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100740DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
741DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200742 cm_service_result_sent == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100743- a USSD request is serviced
744 expecting USSD:
745 Your extension is 42342
Harald Welte80315ef2018-01-24 22:53:00 +0100746 MSC <--RAN_UTRAN_IU-- MS: NCSS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100747DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Harald Welte80315ef2018-01-24 22:53:00 +0100748DRLL Dispatching 04.08 message NCSS:0x3b (0xb:0x3b)
749DMM MSISDN:42342: rx msg NCSS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200750DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
751DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100752DMM USSD: Own number requested
753DMM MSISDN:42342: MSISDN = 42342
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200754DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_UTRAN_IU
Harald Welte80315ef2018-01-24 22:53:00 +0100755- DTAP --RAN_UTRAN_IU--> MS: NCSS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100756- DTAP matches expected message
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100757DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
758DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200759DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
760DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100761DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
762DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
763DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
764DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
765DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200766- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100767DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200768DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
769DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100770DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100771DRLL subscr MSISDN:42342: Freeing subscriber connection
772DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200773 iu_release_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100774- all requests serviced, conn has been released
775 llist_count(&net->subscr_conns) == 0
776---
777- an SMS is sent, MS is paged
778DREF VLR subscr MSISDN:42342 usage increases to: 2
779 llist_count(&vsub->cs.requests) == 0
780DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200781DMM Subscriber MSISDN:42342 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100782 RAN_UTRAN_IU sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200783 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100784DREF VLR subscr MSISDN:42342 usage increases to: 4
785 llist_count(&vsub->cs.requests) == 1
786DREF VLR subscr MSISDN:42342 usage decreases to: 3
787 paging_sent == 1
788 paging_stopped == 0
789- the subscriber and its pending request should remain
790DREF VLR subscr MSISDN:42342 usage increases to: 4
791 llist_count(&vsub->cs.requests) == 1
792DREF VLR subscr MSISDN:42342 usage decreases to: 3
793- MS replies with Paging Response, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100794 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100795 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100796DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100797DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100798DRR PAGING RESPONSE: MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100799DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200800DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
801DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
802DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100803DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
804DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200805DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100806DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
807DREF VLR subscr MSISDN:42342 usage increases to: 4
808DREF VLR subscr MSISDN:42342 usage increases to: 5
809DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
810DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
811DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
812DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
813DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
814DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100815DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100816- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
817- ...rand=efa9c29a9742148d5c9070348716e1bb
818- ...autn=f9375e6d41e1000096e7fe4ff1c27e39
819- ...expecting res=706f996719ba609c
820DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100821DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100822DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100823 auth_request_sent == 1
824- needs auth, not yet accepted
825msc_subscr_conn_is_accepted() == false
826 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100827DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
828DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
829DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
830DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
831DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
832DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +0100833DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
834DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200835- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100836 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100837DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100838DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100839DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 706f996719ba609c)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100840DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100841DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 706f996719ba609c (8 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100842DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
843DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
844DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
845DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
846DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
847DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
848DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
849DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
850DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
851DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100852DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100853DMM -> SECURITY MODE CONTROL MSISDN:42342
854- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
855- ...ik=eb50e770ddcc3060101d2f43b6c2b884
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200856DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100857DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100858DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100859 security_mode_ctrl_sent == 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200860 paging_stopped == 0
861- MS sends SecurityModeControl acceptance, VLR accepts and sends SMS
862DMM <- SECURITY MODE COMPLETE MSISDN:42342
863DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
864DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
865DIUCS MSISDN:42342: tx CommonID 901700000010650
866- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
867DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
868DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
869DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
870DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
871DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
872DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100873DVLR 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 +0200874DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
875DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
876DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
877DPAG Paging success for MSISDN:42342 (event=0)
878DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100879DCC (ti 00 sub MSISDN:42342 callref 40000002) New transaction
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100880DREF VLR subscr MSISDN:42342 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100881DREF MSISDN:42342: MSC conn use + trans_sms == 2 (0x14)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200882DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_UTRAN_IU
Harald Welte80315ef2018-01-24 22:53:00 +0100883- DTAP --RAN_UTRAN_IU--> MS: SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100884- DTAP matches expected message
885DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100886DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
887DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100888 paging_stopped == 1
889- SMS was delivered, no requests pending for subscr
890DREF VLR subscr MSISDN:42342 usage increases to: 5
891 llist_count(&vsub->cs.requests) == 0
892DREF VLR subscr MSISDN:42342 usage decreases to: 4
893- conn is still open to wait for SMS ack dance
894 llist_count(&net->subscr_conns) == 1
895- MS replies with CP-ACK for received SMS
Harald Welte80315ef2018-01-24 22:53:00 +0100896 MSC <--RAN_UTRAN_IU-- MS: SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100897DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100898DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200899DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
900DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100901DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
902DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100903DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100904 llist_count(&net->subscr_conns) == 1
905- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Harald Welte80315ef2018-01-24 22:53:00 +0100906 MSC <--RAN_UTRAN_IU-- MS: SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100907DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Harald Welte80315ef2018-01-24 22:53:00 +0100908DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200909DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
910DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
Harald Welte80315ef2018-01-24 22:53:00 +0100911- DTAP --RAN_UTRAN_IU--> MS: SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100912- DTAP matches expected message
913DREF VLR subscr MSISDN:42342 usage decreases to: 3
914DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100915DREF MSISDN:42342: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100916DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
917DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200918DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
919DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100920DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
921DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
922DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
923DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
924DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200925- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100926DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200927DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
928DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100929DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100930DRLL subscr MSISDN:42342: Freeing subscriber connection
931DREF VLR subscr MSISDN:42342 usage decreases to: 1
932 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200933 iu_release_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100934- SMS is done, conn is gone
935 llist_count(&net->subscr_conns) == 0
936---
937- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100938 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100939 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100940DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100941DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100942DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
943DREF VLR subscr MSISDN:42342 usage increases to: 2
944DMM IMSI DETACH for MSISDN:42342
945DREF VLR subscr MSISDN:42342 usage decreases to: 1
946DREF VLR subscr MSISDN:42342 usage decreases to: 0
947DREF freeing VLR subscr MSISDN:42342
948DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200949- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100950DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100951DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +0200952 iu_release_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100953 llist_count(&net->subscr_conns) == 0
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100954===== test_umts_authen_utran: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100955
956full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte23466192018-02-14 00:19:06 +0100957talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100958
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100959===== test_umts_authen_resync_geran
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100960- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100961 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100962 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100963DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100964DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100965DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200966DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
967DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
968DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100969DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100970DMM LU/new-LAC: 0/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100971DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
972DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
973DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth (no Ciph)
974DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
975DREF VLR subscr unknown usage increases to: 1
976DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
977DVLR New subscr, IMSI: 901700000010650
978DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200979DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100980DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
981DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
982DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
983DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
984DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
985DVLR GSUP tx: 08010809710000000156f0
986GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
987DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100988DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100989DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100990 lu_result_sent == 0
991- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
992<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
993DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
994DREF VLR subscr IMSI:901700000010650 usage increases to: 2
995DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
996DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples
997DVLR 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 +0100998DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100999- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1000- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1001- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1002- ...expecting res=e229c19e791f2e41
1003DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1004<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1005 auth_request_sent == 1
1006 lu_result_sent == 0
1007- MS sends Authen Failure with Resync cause, VLR sends GSUP to HLR to resync
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001008 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_FAIL
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001009DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001010DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_FAIL (0x5:0x1c)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001011DMM IMSI:901700000010650: MM R99 AUTHENTICATION SYNCH (AUTS = 979498b1f72d3e28c59fa2e72f9c)
1012DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_FAIL
1013DVLR GSUP tx: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
1014GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
1015DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001016DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001017DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001018 gsup_tx_confirmed == 1
1019 auth_request_sent == 0
1020 lu_result_sent == 0
1021- HLR replies with new tuples
1022<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
1023DVLR GSUP rx 211: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
1024DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1025DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1026DVLR SUBSCR(IMSI:901700000010650) Received 2 auth tuples
1027DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: state_chg to VLR_SUB_AS_WAIT_RESP_RESYNC
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001028DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001029- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1030- ...rand=0f1feb1623e1bf626334e37ec448ac18
1031- ...autn=02a83f62e9470000660d51afc75f169d
1032- ...expecting res=1df5f0b4f22b696e
1033DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1034<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1035 auth_request_sent == 1
1036 lu_result_sent == 0
1037- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001038 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001039DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001040DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +01001041DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = 1df5f0b4f22b696e)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001042DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001043DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: 1df5f0b4f22b696e (8 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001044DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
1045DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Authentication terminating with result VLR_AUTH_RES_PASSED
1046DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: state_chg to VLR_SUB_AS_AUTHENTICATED
1047DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1048DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
1049DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1050DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1051DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1052DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1053DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1054DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1055DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1056DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1057DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1058DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1059DVLR GSUP tx: 04010809710000000156f0
1060GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
1061DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001062DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001063DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001064 gsup_tx_confirmed == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001065 lu_result_sent == 0
1066- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1067<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1068DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1069DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1070DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +01001071DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001072DVLR GSUP tx: 12010809710000000156f0
1073GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1074DREF VLR subscr MSISDN:42342 usage decreases to: 1
1075<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1076 lu_result_sent == 0
1077- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1078<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1079DVLR GSUP rx 11: 06010809710000000156f0
1080DREF VLR subscr MSISDN:42342 usage increases to: 2
1081DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1082DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1083DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1084DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1085DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1086DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1087DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1088DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1089DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1090DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1091DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1092DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1093DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1094DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1095DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
1096DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1097DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1098DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1099DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
1100DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1101DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1102DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001103DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1104DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1105- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
1106DREF VLR subscr MSISDN:42342 usage decreases to: 1
1107<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1108 lu_result_sent == 1
1109- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1110 llist_count(&net->subscr_conns) == 1
1111msc_subscr_conn_is_accepted() == false
1112 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001113DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1114DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1115DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1116DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
1117DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1118DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001119DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1120DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001121- even though the TMSI is not acked, we can already find the subscr with it
1122DREF VLR subscr MSISDN:42342 usage increases to: 2
1123 vsub != NULL == 1
1124 strcmp(vsub->imsi, imsi) == 0
1125 vsub->tmsi_new == 0x03020100
1126 vsub->tmsi == 0xffffffff
1127DREF VLR subscr MSISDN:42342 usage decreases to: 1
1128- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001129 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001130DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001131DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001132DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
1133DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1134DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1135DREF VLR subscr MSISDN:42342 usage increases to: 2
1136DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001137DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1138DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1139DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1140DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1141DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1142DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001143DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1144DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1145DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001146DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1147DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001148DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1149DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001150DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1151DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1152DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1153DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1154DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1155DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +02001156- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001157DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001158DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1159DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001160DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001161DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001162DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001163 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001164- LU was successful, and the conn has already been closed
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001165 llist_count(&net->subscr_conns) == 0
1166DREF freeing VLR subscr MSISDN:42342
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001167===== test_umts_authen_resync_geran: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001168
1169full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte23466192018-02-14 00:19:06 +01001170talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001171
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001172===== test_umts_authen_resync_utran
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001173- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001174 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001175 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001176DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001177DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001178DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001179DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1180DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1181DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001182DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +01001183DMM LU/new-LAC: 0/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001184DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1185DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001186DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001187DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1188DREF VLR subscr unknown usage increases to: 1
1189DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1190DVLR New subscr, IMSI: 901700000010650
1191DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +02001192DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001193DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1194DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1195DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1196DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1197DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1198DVLR GSUP tx: 08010809710000000156f0
1199GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1200DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001201DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001202DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001203 lu_result_sent == 0
1204- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1205<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
1206DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
1207DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1208DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1209DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples
1210DVLR 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 +01001211DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001212- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1213- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1214- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1215- ...expecting res=e229c19e791f2e41
1216DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1217<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1218 auth_request_sent == 1
1219 lu_result_sent == 0
1220- MS sends Authen Failure with Resync cause, VLR sends GSUP to HLR to resync
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001221 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_FAIL
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001222DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001223DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_FAIL (0x5:0x1c)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001224DMM IMSI:901700000010650: MM R99 AUTHENTICATION SYNCH (AUTS = 979498b1f72d3e28c59fa2e72f9c)
1225DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_FAIL
1226DVLR GSUP tx: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
1227GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
1228DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001229DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001230DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001231 gsup_tx_confirmed == 1
1232 auth_request_sent == 0
1233 lu_result_sent == 0
1234- HLR replies with new tuples
1235<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
1236DVLR GSUP rx 211: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
1237DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1238DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1239DVLR SUBSCR(IMSI:901700000010650) Received 2 auth tuples
1240DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: state_chg to VLR_SUB_AS_WAIT_RESP_RESYNC
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +01001241DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001242- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1243- ...rand=0f1feb1623e1bf626334e37ec448ac18
1244- ...autn=02a83f62e9470000660d51afc75f169d
1245- ...expecting res=1df5f0b4f22b696e
1246DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1247<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1248 auth_request_sent == 1
1249 lu_result_sent == 0
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001250- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001251 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001252DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001253DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +01001254DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = 1df5f0b4f22b696e)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001255DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001256DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: 1df5f0b4f22b696e (8 bytes)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001257DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
1258DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Authentication terminating with result VLR_AUTH_RES_PASSED
1259DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: state_chg to VLR_SUB_AS_AUTHENTICATED
1260DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1261DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
1262DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1263DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1264DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1265DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +01001266DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +01001267DMM -> SECURITY MODE CONTROL IMSI:901700000010650
1268- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1269- ...ik=8a90c769b7272f3bb7a1c1fbb1ea9349
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001270DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001271DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001272DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +01001273 security_mode_ctrl_sent == 1
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001274 lu_result_sent == 0
1275- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
1276DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
1277DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1278DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
1279DIUCS IMSI:901700000010650: tx CommonID 901700000010650
1280- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
1281DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1282DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001283DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1284DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1285DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1286DVLR GSUP tx: 04010809710000000156f0
1287GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
1288DVLR 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 +02001289 gsup_tx_confirmed == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001290 lu_result_sent == 0
1291- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1292<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1293DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1294DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1295DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +01001296DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001297DVLR GSUP tx: 12010809710000000156f0
1298GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1299DREF VLR subscr MSISDN:42342 usage decreases to: 1
1300<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1301 lu_result_sent == 0
1302- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1303<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1304DVLR GSUP rx 11: 06010809710000000156f0
1305DREF VLR subscr MSISDN:42342 usage increases to: 2
1306DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1307DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1308DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1309DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1310DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1311DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1312DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1313DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1314DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1315DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1316DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1317DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1318DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1319DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1320DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
1321DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1322DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1323DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1324DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
1325DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1326DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1327DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001328DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1329DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1330- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
1331DREF VLR subscr MSISDN:42342 usage decreases to: 1
1332<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1333 lu_result_sent == 1
1334- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1335 llist_count(&net->subscr_conns) == 1
1336msc_subscr_conn_is_accepted() == false
1337 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001338DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1339DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1340DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1341DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
1342DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1343DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
Harald Welte80315ef2018-01-24 22:53:00 +01001344DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
1345DRLL subscr MSISDN:42342: Message not permitted for initial conn: SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001346- even though the TMSI is not acked, we can already find the subscr with it
1347DREF VLR subscr MSISDN:42342 usage increases to: 2
1348 vsub != NULL == 1
1349 strcmp(vsub->imsi, imsi) == 0
1350 vsub->tmsi_new == 0x03020100
1351 vsub->tmsi == 0xffffffff
1352DREF VLR subscr MSISDN:42342 usage decreases to: 1
1353- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001354 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001355DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +01001356DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001357DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
1358DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1359DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1360DREF VLR subscr MSISDN:42342 usage increases to: 2
1361DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001362DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1363DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1364DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1365DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1366DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1367DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001368DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1369DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1370DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001371DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1372DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001373DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1374DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001375DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1376DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1377DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1378DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1379DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1380DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001381- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001382DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +02001383DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1384DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +01001385DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001386DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001387DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +02001388 iu_release_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001389- LU was successful, and the conn has already been closed
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001390 llist_count(&net->subscr_conns) == 0
1391DREF freeing VLR subscr MSISDN:42342
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +01001392===== test_umts_authen_resync_utran: SUCCESS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001393
1394full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte23466192018-02-14 00:19:06 +01001395talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001396
Neels Hofmeyr15ed4262018-03-10 04:02:44 +01001397===== test_umts_authen_too_short_res_geran
1398- Location Update request causes a GSUP Send Auth Info request to HLR
1399 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1400 new conn
1401DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1402DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
1403DREF unknown: MSC conn use + fsm == 2 (0x5)
1404DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1405DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1406DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1407DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1408DMM LU/new-LAC: 0/23
1409DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1410DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1411DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth (no Ciph)
1412DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1413DREF VLR subscr unknown usage increases to: 1
1414DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1415DVLR New subscr, IMSI: 901700000010650
1416DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1417DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1418DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1419DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1420DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1421DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1422DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1423DVLR GSUP tx: 08010809710000000156f0
1424GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1425DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001426DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr15ed4262018-03-10 04:02:44 +01001427DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
1428 lu_result_sent == 0
1429- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1430<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1431DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1432DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1433DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1434DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
1435DVLR 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 +01001436DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr15ed4262018-03-10 04:02:44 +01001437- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1438- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1439- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1440- ...expecting res=e229c19e791f2e41
1441DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1442<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1443 auth_request_sent == 1
1444 lu_result_sent == 0
1445- MS sends Authen Response of wrong RES size, VLR thwarts
1446 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
1447DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
1448DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1449DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e)
1450DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001451DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: e229c19e791f2e (7 bytes)
Neels Hofmeyr11d2ce32018-03-10 00:25:20 +01001452DVLR SUBSCR(IMSI:901700000010650) AUTH SRES/RES has invalid length: 7. Expected either 4 (GSM AKA) or 8 (UMTS AKA)
Neels Hofmeyr15ed4262018-03-10 04:02:44 +01001453DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_AUTH_FAILED
1454DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTH_FAILED
1455DVLR GSUP tx: 0b010809710000000156f0
1456GSUP --> HLR: OSMO_GSUP_MSGT_AUTH_FAIL_REPORT: 0b010809710000000156f0
1457DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1458DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Removing from parent vlr_lu_fsm(901700000010650)
1459DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Freeing instance
1460DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Deallocated
1461DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1462- sending LU Reject for IMSI:901700000010650, cause 3
1463DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
1464DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
1465DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1466DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Close event, cause 1
1467DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
1468DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1469DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1470DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1471DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1472DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1473DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1474DMM msc_subscr_conn_close(vsub=IMSI:901700000010650, cause=2): no conn fsm, releasing directly without release event.
1475- BSSAP Clear --RAN_GERAN_A--> MS
1476DREF IMSI:901700000010650: MSC conn use - fsm == 1 (0x2)
1477DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1478DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1479DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0)
1480DRLL subscr IMSI:901700000010650: Freeing subscriber connection
1481DREF VLR subscr IMSI:901700000010650 usage decreases to: 0
1482DREF freeing VLR subscr IMSI:901700000010650
1483 lu_result_sent == 2
1484 bssap_clear_sent == 1
1485 llist_count(&net->subscr_conns) == 0
1486===== test_umts_authen_too_short_res_geran: SUCCESS
1487
1488full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1489talloc_total_blocks(tall_bsc_ctx) == 7
1490
1491===== test_umts_authen_too_short_res_utran
1492- Location Update request causes a GSUP Send Auth Info request to HLR
1493 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1494 new conn
1495DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1496DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
1497DREF unknown: MSC conn use + fsm == 2 (0x5)
1498DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1499DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1500DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1501DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1502DMM LU/new-LAC: 0/23
1503DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1504DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1505DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
1506DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1507DREF VLR subscr unknown usage increases to: 1
1508DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1509DVLR New subscr, IMSI: 901700000010650
1510DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1511DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1512DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1513DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1514DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1515DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1516DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1517DVLR GSUP tx: 08010809710000000156f0
1518GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1519DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001520DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr15ed4262018-03-10 04:02:44 +01001521DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
1522 lu_result_sent == 0
1523- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1524<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1525DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1526DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1527DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1528DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
1529DVLR 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 +01001530DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr15ed4262018-03-10 04:02:44 +01001531- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1532- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1533- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1534- ...expecting res=e229c19e791f2e41
1535DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1536<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1537 auth_request_sent == 1
1538 lu_result_sent == 0
1539- MS sends Authen Response of wrong RES size, VLR thwarts
1540 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
1541DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
1542DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1543DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e)
1544DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001545DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e (7 bytes)
Neels Hofmeyr11d2ce32018-03-10 00:25:20 +01001546DVLR SUBSCR(IMSI:901700000010650) AUTH RES has invalid length: 7. Expected 8 (UMTS AKA)
Neels Hofmeyr15ed4262018-03-10 04:02:44 +01001547DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_AUTH_FAILED
1548DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTH_FAILED
1549DVLR GSUP tx: 0b010809710000000156f0
1550GSUP --> HLR: OSMO_GSUP_MSGT_AUTH_FAIL_REPORT: 0b010809710000000156f0
1551DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1552DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Removing from parent vlr_lu_fsm(901700000010650)
1553DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Freeing instance
1554DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Deallocated
1555DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1556- sending LU Reject for IMSI:901700000010650, cause 3
1557DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
1558DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
1559DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1560DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Close event, cause 1
1561DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
1562DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1563DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1564DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1565DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1566DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1567DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1568DMM msc_subscr_conn_close(vsub=IMSI:901700000010650, cause=2): no conn fsm, releasing directly without release event.
1569- Iu Release --RAN_UTRAN_IU--> MS
1570DREF IMSI:901700000010650: MSC conn use - fsm == 1 (0x2)
1571DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1572DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1573DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0)
1574DRLL subscr IMSI:901700000010650: Freeing subscriber connection
1575DREF VLR subscr IMSI:901700000010650 usage decreases to: 0
1576DREF freeing VLR subscr IMSI:901700000010650
1577 lu_result_sent == 2
1578 iu_release_sent == 1
1579 llist_count(&net->subscr_conns) == 0
1580===== test_umts_authen_too_short_res_utran: SUCCESS
1581
1582full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1583talloc_total_blocks(tall_bsc_ctx) == 7
1584
Neels Hofmeyrc6d20dd2018-03-10 04:03:43 +01001585===== test_umts_authen_too_long_res_geran
1586- Location Update request causes a GSUP Send Auth Info request to HLR
1587 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1588 new conn
1589DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1590DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
1591DREF unknown: MSC conn use + fsm == 2 (0x5)
1592DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1593DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1594DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1595DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1596DMM LU/new-LAC: 0/23
1597DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1598DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1599DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth (no Ciph)
1600DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1601DREF VLR subscr unknown usage increases to: 1
1602DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1603DVLR New subscr, IMSI: 901700000010650
1604DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1605DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1606DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1607DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1608DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1609DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1610DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1611DVLR GSUP tx: 08010809710000000156f0
1612GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1613DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001614DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrc6d20dd2018-03-10 04:03:43 +01001615DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
1616 lu_result_sent == 0
1617- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1618<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1619DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1620DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1621DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1622DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
1623DVLR 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 +01001624DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyrc6d20dd2018-03-10 04:03:43 +01001625- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1626- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1627- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1628- ...expecting res=e229c19e791f2e41
1629DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1630<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1631 auth_request_sent == 1
1632 lu_result_sent == 0
1633- MS sends Authen Response of wrong RES size, VLR thwarts
1634 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
1635DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
1636DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1637DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e4123)
1638DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001639DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: e229c19e791f2e4123 (9 bytes)
Neels Hofmeyr11d2ce32018-03-10 00:25:20 +01001640DVLR SUBSCR(IMSI:901700000010650) AUTH SRES/RES has invalid length: 9. Expected either 4 (GSM AKA) or 8 (UMTS AKA)
Neels Hofmeyrc6d20dd2018-03-10 04:03:43 +01001641DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_AUTH_FAILED
1642DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTH_FAILED
1643DVLR GSUP tx: 0b010809710000000156f0
1644GSUP --> HLR: OSMO_GSUP_MSGT_AUTH_FAIL_REPORT: 0b010809710000000156f0
1645DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1646DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Removing from parent vlr_lu_fsm(901700000010650)
1647DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Freeing instance
1648DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Deallocated
1649DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1650- sending LU Reject for IMSI:901700000010650, cause 3
1651DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
1652DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
1653DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1654DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Close event, cause 1
1655DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
1656DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1657DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1658DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1659DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1660DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1661DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1662DMM msc_subscr_conn_close(vsub=IMSI:901700000010650, cause=2): no conn fsm, releasing directly without release event.
1663- BSSAP Clear --RAN_GERAN_A--> MS
1664DREF IMSI:901700000010650: MSC conn use - fsm == 1 (0x2)
1665DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1666DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1667DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0)
1668DRLL subscr IMSI:901700000010650: Freeing subscriber connection
1669DREF VLR subscr IMSI:901700000010650 usage decreases to: 0
1670DREF freeing VLR subscr IMSI:901700000010650
1671 lu_result_sent == 2
1672 bssap_clear_sent == 1
1673 llist_count(&net->subscr_conns) == 0
1674===== test_umts_authen_too_long_res_geran: SUCCESS
1675
1676full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1677talloc_total_blocks(tall_bsc_ctx) == 7
1678
1679===== test_umts_authen_too_long_res_utran
1680- Location Update request causes a GSUP Send Auth Info request to HLR
1681 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1682 new conn
1683DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1684DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
1685DREF unknown: MSC conn use + fsm == 2 (0x5)
1686DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1687DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1688DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1689DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1690DMM LU/new-LAC: 0/23
1691DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1692DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1693DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
1694DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1695DREF VLR subscr unknown usage increases to: 1
1696DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1697DVLR New subscr, IMSI: 901700000010650
1698DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1699DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1700DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1701DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1702DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1703DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1704DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1705DVLR GSUP tx: 08010809710000000156f0
1706GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1707DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001708DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyrc6d20dd2018-03-10 04:03:43 +01001709DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
1710 lu_result_sent == 0
1711- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1712<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1713DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1714DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1715DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1716DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
1717DVLR 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 +01001718DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyrc6d20dd2018-03-10 04:03:43 +01001719- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1720- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1721- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1722- ...expecting res=e229c19e791f2e41
1723DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1724<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1725 auth_request_sent == 1
1726 lu_result_sent == 0
1727- MS sends Authen Response of wrong RES size, VLR thwarts
1728 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
1729DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
1730DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1731DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e4123)
1732DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001733DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e4123 (9 bytes)
Neels Hofmeyr11d2ce32018-03-10 00:25:20 +01001734DVLR SUBSCR(IMSI:901700000010650) AUTH RES has invalid length: 9. Expected 8 (UMTS AKA)
Neels Hofmeyrc6d20dd2018-03-10 04:03:43 +01001735DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_AUTH_FAILED
1736DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTH_FAILED
1737DVLR GSUP tx: 0b010809710000000156f0
1738GSUP --> HLR: OSMO_GSUP_MSGT_AUTH_FAIL_REPORT: 0b010809710000000156f0
1739DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1740DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Removing from parent vlr_lu_fsm(901700000010650)
1741DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Freeing instance
1742DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Deallocated
1743DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1744- sending LU Reject for IMSI:901700000010650, cause 3
1745DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
1746DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
1747DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1748DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Close event, cause 1
1749DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
1750DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1751DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1752DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1753DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1754DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1755DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1756DMM msc_subscr_conn_close(vsub=IMSI:901700000010650, cause=2): no conn fsm, releasing directly without release event.
1757- Iu Release --RAN_UTRAN_IU--> MS
1758DREF IMSI:901700000010650: MSC conn use - fsm == 1 (0x2)
1759DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1760DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1761DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0)
1762DRLL subscr IMSI:901700000010650: Freeing subscriber connection
1763DREF VLR subscr IMSI:901700000010650 usage decreases to: 0
1764DREF freeing VLR subscr IMSI:901700000010650
1765 lu_result_sent == 2
1766 iu_release_sent == 1
1767 llist_count(&net->subscr_conns) == 0
1768===== test_umts_authen_too_long_res_utran: SUCCESS
1769
1770full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1771talloc_total_blocks(tall_bsc_ctx) == 7
1772
Neels Hofmeyr31adcae2018-03-10 04:08:45 +01001773===== test_umts_authen_only_sres_geran
1774- Location Update request causes a GSUP Send Auth Info request to HLR
1775 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1776 new conn
1777DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1778DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
1779DREF unknown: MSC conn use + fsm == 2 (0x5)
1780DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1781DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1782DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1783DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1784DMM LU/new-LAC: 0/23
1785DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1786DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1787DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth (no Ciph)
1788DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1789DREF VLR subscr unknown usage increases to: 1
1790DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1791DVLR New subscr, IMSI: 901700000010650
1792DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1793DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1794DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1795DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1796DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1797DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1798DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1799DVLR GSUP tx: 08010809710000000156f0
1800GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1801DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001802DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr31adcae2018-03-10 04:08:45 +01001803DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
1804 lu_result_sent == 0
1805- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1806<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1807DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1808DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1809DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1810DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
1811DVLR 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 +01001812DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr31adcae2018-03-10 04:08:45 +01001813- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1814- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1815- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1816- ...expecting res=e229c19e791f2e41
1817DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1818<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1819 auth_request_sent == 1
1820 lu_result_sent == 0
1821- MS sends Authen Response of wrong RES size, VLR thwarts: GERAN reports an SRES mismatch
1822 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
1823DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
1824DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1825DMM IMSI:901700000010650: MM GSM AUTHENTICATION RESPONSE (sres = e229c19e)
1826DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001827DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: e229c19e (4 bytes)
Neels Hofmeyr31adcae2018-03-10 04:08:45 +01001828DVLR SUBSCR(IMSI:901700000010650) GSM AUTH failure: mismatching sres (expected sres=9b 36 ef df )
1829DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_AUTH_FAILED
1830DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTH_FAILED
1831DVLR GSUP tx: 0b010809710000000156f0
1832GSUP --> HLR: OSMO_GSUP_MSGT_AUTH_FAIL_REPORT: 0b010809710000000156f0
1833DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1834DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Removing from parent vlr_lu_fsm(901700000010650)
1835DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Freeing instance
1836DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Deallocated
1837DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1838- sending LU Reject for IMSI:901700000010650, cause 3
1839DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
1840DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
1841DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1842DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Close event, cause 1
1843DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
1844DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1845DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1846DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1847DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1848DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1849DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1850DMM msc_subscr_conn_close(vsub=IMSI:901700000010650, cause=2): no conn fsm, releasing directly without release event.
1851- BSSAP Clear --RAN_GERAN_A--> MS
1852DREF IMSI:901700000010650: MSC conn use - fsm == 1 (0x2)
1853DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1854DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1855DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0)
1856DRLL subscr IMSI:901700000010650: Freeing subscriber connection
1857DREF VLR subscr IMSI:901700000010650 usage decreases to: 0
1858DREF freeing VLR subscr IMSI:901700000010650
1859 lu_result_sent == 2
1860 bssap_clear_sent == 1
1861 llist_count(&net->subscr_conns) == 0
1862===== test_umts_authen_only_sres_geran: SUCCESS
1863
1864full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1865talloc_total_blocks(tall_bsc_ctx) == 7
1866
1867===== test_umts_authen_only_sres_utran
1868- Location Update request causes a GSUP Send Auth Info request to HLR
1869 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1870 new conn
1871DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1872DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
1873DREF unknown: MSC conn use + fsm == 2 (0x5)
1874DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1875DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1876DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
1877DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1878DMM LU/new-LAC: 0/23
1879DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1880DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1881DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
1882DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1883DREF VLR subscr unknown usage increases to: 1
1884DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1885DVLR New subscr, IMSI: 901700000010650
1886DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1887DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1888DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1889DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1890DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1891DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1892DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1893DVLR GSUP tx: 08010809710000000156f0
1894GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1895DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +01001896DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr31adcae2018-03-10 04:08:45 +01001897DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
1898 lu_result_sent == 0
1899- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1900<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1901DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1902DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1903DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1904DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
1905DVLR 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 +01001906DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3)
Neels Hofmeyr31adcae2018-03-10 04:08:45 +01001907- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1908- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1909- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1910- ...expecting res=e229c19e791f2e41
1911DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1912<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1913 auth_request_sent == 1
1914 lu_result_sent == 0
1915- MS sends Authen Response of wrong RES size, VLR thwarts: UTRAN disallows GSM AKA altogether
1916 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
1917DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
1918DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1919DMM IMSI:901700000010650: MM GSM AUTHENTICATION RESPONSE (sres = e229c19e)
1920DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +01001921DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e (4 bytes)
Neels Hofmeyr11d2ce32018-03-10 00:25:20 +01001922DVLR SUBSCR(IMSI:901700000010650) AUTH via UTRAN, cannot allow GSM AKA (MS is R99 capable, vec has UMTS AKA tokens, res_len=4 is INVALID on UTRAN)
Neels Hofmeyr31adcae2018-03-10 04:08:45 +01001923DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_AUTH_FAILED
1924DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTH_FAILED
1925DVLR GSUP tx: 0b010809710000000156f0
1926GSUP --> HLR: OSMO_GSUP_MSGT_AUTH_FAIL_REPORT: 0b010809710000000156f0
1927DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1928DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Removing from parent vlr_lu_fsm(901700000010650)
1929DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Freeing instance
1930DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTH_FAILED}: Deallocated
1931DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1932- sending LU Reject for IMSI:901700000010650, cause 3
1933DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_DONE
1934DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE
1935DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1936DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Close event, cause 1
1937DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASED
1938DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1939DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1940DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1941DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1942DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1943DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1944DMM msc_subscr_conn_close(vsub=IMSI:901700000010650, cause=2): no conn fsm, releasing directly without release event.
1945- Iu Release --RAN_UTRAN_IU--> MS
1946DREF IMSI:901700000010650: MSC conn use - fsm == 1 (0x2)
1947DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1948DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1949DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0)
1950DRLL subscr IMSI:901700000010650: Freeing subscriber connection
1951DREF VLR subscr IMSI:901700000010650 usage decreases to: 0
1952DREF freeing VLR subscr IMSI:901700000010650
1953 lu_result_sent == 2
1954 iu_release_sent == 1
1955 llist_count(&net->subscr_conns) == 0
1956===== test_umts_authen_only_sres_utran: SUCCESS
1957
1958full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1959talloc_total_blocks(tall_bsc_ctx) == 7
1960
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001961full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte23466192018-02-14 00:19:06 +01001962talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr6a29d322017-01-25 15:04:16 +01001963