Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / 4cf4fddf287edb171939c5585db576be9addd474 / . / tests / msc_vlr / msc_vlr_test_umts_authen.err
blob: 41bdf4903812170702eade2437d1de787018916a [file] [log] [blame]
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1===== test_umts_authen_geran
2- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]3 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]4 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]5DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]6DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]7DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]8DMM 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 +0100[diff] [blame]11DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]12DMM LU/new-LAC: 0/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]13DVLR 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 +0200[diff] [blame]21DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]22DVLR 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 Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]30DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]31DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]32 lu_result_sent == 0
33- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
34<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 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
40DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
41- 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 +0100[diff] [blame]50 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]51DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]52DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]53DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
54DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
55DVLR SUBSCR(IMSI:901700000010650) received res: e2 29 c1 9e 79 1f 2e 41
56DVLR 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 Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]74DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]75DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]76 gsup_tx_confirmed == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]77 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
83DVLR GSUP tx: 12010809710000000156f0
84GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
85DREF VLR subscr MSISDN:42342 usage decreases to: 1
86<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
87 lu_result_sent == 0
88- HLR also sends GSUP _UPDATE_LOCATION_RESULT
89<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
90DVLR GSUP rx 11: 06010809710000000156f0
91DREF VLR subscr MSISDN:42342 usage increases to: 2
92DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
93DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
94DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
95DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
96DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
97DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
98DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
99DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
100DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
101DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
102DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
103DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
104DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
105DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
106DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
107DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
108DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
109DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
110DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
111DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
112DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
113DVLR 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 +0200[diff] [blame]114DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
115DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
116- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
117DREF VLR subscr MSISDN:42342 usage decreases to: 1
118<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
119 lu_result_sent == 1
120- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
121 llist_count(&net->subscr_conns) == 1
122msc_subscr_conn_is_accepted() == false
123 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]124DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
125DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
126DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
127DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
128DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
129DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
130DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x01 (0x9:0x1)
131DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_PDISC_SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]132- even though the TMSI is not acked, we can already find the subscr with it
133DREF VLR subscr MSISDN:42342 usage increases to: 2
134 vsub != NULL == 1
135 strcmp(vsub->imsi, imsi) == 0
136 vsub->tmsi_new == 0x03020100
137 vsub->tmsi == 0xffffffff
138DREF VLR subscr MSISDN:42342 usage decreases to: 1
139- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]140 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]141DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]142DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]143DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
144DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
145DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
146DREF VLR subscr MSISDN:42342 usage increases to: 2
147DVLR 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 +0100[diff] [blame]148DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
149DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
150DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
151DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
152DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
153DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]154DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
155DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
156DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
157DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
158DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
159DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
160DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]161DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
162DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
163DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
164DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
165DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
166DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]167- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]168DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]169DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
170DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]171DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]172DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]173DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]174 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]175- LU was successful, and the conn has already been closed
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]176 llist_count(&net->subscr_conns) == 0
177---
178- 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 +0100[diff] [blame]179 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]180 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]181DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]182DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]183DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]184DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]185DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
186DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
187DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]188DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
189DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
190DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth (no Ciph)
191DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
192DREF VLR subscr MSISDN:42342 usage increases to: 2
193DREF VLR subscr MSISDN:42342 usage increases to: 3
194DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
195DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
196DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
197DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
198DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
199DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
200DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
201- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
202- ...rand=c187a53a5e6b9d573cac7c74451fd46d
203- ...autn=1843a645b98d00005b2d666af46c45d9
204- ...expecting res=7db47cf7f81e4dc7
205DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]206DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]207DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]208 cm_service_result_sent == 0
209 auth_request_sent == 1
210- needs auth, not yet accepted
211msc_subscr_conn_is_accepted() == false
212 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]213DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
214DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
215DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
216DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
217DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
218DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
219DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x01 (0x9:0x1)
220DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_PDISC_SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]221- MS sends Authen Response, VLR accepts with a CM Service Accept
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]222 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]223DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]224DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]225DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
226DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
227DVLR SUBSCR(MSISDN:42342) received res: 7d b4 7c f7 f8 1e 4d c7
228DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
229DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
230DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
231DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
232DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
233DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
234DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
235DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
236DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
237DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
238DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
239DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
240DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
241DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
242DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
243DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
244DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
245DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
246- sending CM Service Accept for MSISDN:42342
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]247DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
248DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
249DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
250DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
251DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
252DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
253DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
254DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]255DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]256 cm_service_result_sent == 1
257- a USSD request is serviced
258 expecting USSD:
259 Your extension is 42342
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]260 MSC <--RAN_GERAN_A-- MS: GSM48_PDISC_NC_SS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]261DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]262DRLL Dispatching 04.08 message GSM48_PDISC_NC_SS:0x3b (0xb:0x3b)
263DMM MSISDN:42342: rx msg GSM48_PDISC_NC_SS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]264DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
265DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]266DMM USSD: Own number requested
267DMM MSISDN:42342: MSISDN = 42342
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]268DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]269- DTAP --RAN_GERAN_A--> MS: GSM48_PDISC_NC_SS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]270- DTAP matches expected message
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]271DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
272DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
273DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
274DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]275DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
276DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
277DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
278DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
279DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]280- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]281DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]282DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
283DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]284DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]285DRLL subscr MSISDN:42342: Freeing subscriber connection
286DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]287 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]288- all requests serviced, conn has been released
289 llist_count(&net->subscr_conns) == 0
290---
291- an SMS is sent, MS is paged
292DREF VLR subscr MSISDN:42342 usage increases to: 2
293 llist_count(&vsub->cs.requests) == 0
294DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]295DMM Subscriber MSISDN:42342 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]296 RAN_GERAN_A sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]297 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]298DREF VLR subscr MSISDN:42342 usage increases to: 4
299 llist_count(&vsub->cs.requests) == 1
300DREF VLR subscr MSISDN:42342 usage decreases to: 3
301 paging_sent == 1
302 paging_stopped == 0
303- the subscriber and its pending request should remain
304DREF VLR subscr MSISDN:42342 usage increases to: 4
305 llist_count(&vsub->cs.requests) == 1
306DREF VLR subscr MSISDN:42342 usage decreases to: 3
307- MS replies with Paging Response, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]308 MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]309 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]310DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]311DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]312DRR PAGING RESPONSE: MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]313DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]314DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
315DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
316DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]317DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
318DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
319DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth (no Ciph)
320DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
321DREF VLR subscr MSISDN:42342 usage increases to: 4
322DREF VLR subscr MSISDN:42342 usage increases to: 5
323DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
324DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
325DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
326DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
327DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
328DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
329DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2
330- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
331- ...rand=efa9c29a9742148d5c9070348716e1bb
332- ...autn=f9375e6d41e1000096e7fe4ff1c27e39
333- ...expecting res=706f996719ba609c
334DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]335DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]336DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]337 auth_request_sent == 1
338- needs auth, not yet accepted
339msc_subscr_conn_is_accepted() == false
340 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]341DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
342DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
343DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
344DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
345DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
346DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
347DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x01 (0x9:0x1)
348DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_PDISC_SMS:0x01
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]349- MS sends Authen Response, VLR accepts and sends pending SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]350 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]351DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]352DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]353DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 706f996719ba609c)
354DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
355DVLR SUBSCR(MSISDN:42342) received res: 70 6f 99 67 19 ba 60 9c
356DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
357DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
358DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
359DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
360DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
361DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
362DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
363DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
364DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
365DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
366DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
367DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
368DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
369DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
370DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
371DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
372DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
373DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]374DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
375DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
376DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
377DPAG Paging success for MSISDN:42342 (event=0)
378DPAG Calling paging cbfn.
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]379DREF VLR subscr MSISDN:42342 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]380DREF MSISDN:42342: MSC conn use + trans_sms == 3 (0x16)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]381DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]382- DTAP --RAN_GERAN_A--> MS: GSM48_PDISC_SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]383- DTAP matches expected message
384DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]385DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
386DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_SMS
387DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
388DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]389DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]390 dtap_tx_confirmed == 1
391 paging_stopped == 1
392- SMS was delivered, no requests pending for subscr
393DREF VLR subscr MSISDN:42342 usage increases to: 5
394 llist_count(&vsub->cs.requests) == 0
395DREF VLR subscr MSISDN:42342 usage decreases to: 4
396- conn is still open to wait for SMS ack dance
397 llist_count(&net->subscr_conns) == 1
398- MS replies with CP-ACK for received SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]399 MSC <--RAN_GERAN_A-- MS: GSM48_PDISC_SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]400DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]401DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]402DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
403DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
404DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
405DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]406DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]407 llist_count(&net->subscr_conns) == 1
408- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]409 MSC <--RAN_GERAN_A-- MS: GSM48_PDISC_SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]410DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]411DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]412DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
413DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_GERAN_A
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]414- DTAP --RAN_GERAN_A--> MS: GSM48_PDISC_SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]415- DTAP matches expected message
416DREF VLR subscr MSISDN:42342 usage decreases to: 3
417DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]418DREF MSISDN:42342: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]419DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
420DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
421DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
422DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]423DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
424DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
425DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
426DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
427DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]428- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]429DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]430DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
431DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]432DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]433DRLL subscr MSISDN:42342: Freeing subscriber connection
434DREF VLR subscr MSISDN:42342 usage decreases to: 1
435 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]436 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]437- SMS is done, conn is gone
438 llist_count(&net->subscr_conns) == 0
439---
440- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]441 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]442 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]443DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]444DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]445DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
446DREF VLR subscr MSISDN:42342 usage increases to: 2
447DMM IMSI DETACH for MSISDN:42342
448DREF VLR subscr MSISDN:42342 usage decreases to: 1
449DREF VLR subscr MSISDN:42342 usage decreases to: 0
450DREF freeing VLR subscr MSISDN:42342
451DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]452- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]453DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]454DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]455 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]456 llist_count(&net->subscr_conns) == 0
457===== test_umts_authen_geran: SUCCESS
458
459full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]460talloc_total_blocks(tall_bsc_ctx) == 9
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]461
462===== test_umts_authen_utran
463- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]464 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]465 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]466DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]467DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]468DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]469DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
470DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
471DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]472DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]473DMM LU/new-LAC: 0/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]474DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
475DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]476DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]477DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
478DREF VLR subscr unknown usage increases to: 1
479DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
480DVLR New subscr, IMSI: 901700000010650
481DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]482DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]483DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
484DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
485DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
486DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
487DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
488DVLR GSUP tx: 08010809710000000156f0
489GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
490DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]491DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]492DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]493 lu_result_sent == 0
494- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
495<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
496DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
497DREF VLR subscr IMSI:901700000010650 usage increases to: 2
498DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
499DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
500DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
501DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
502- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
503- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
504- ...autn=8704f5ba55f30000d2ee44b22c8ea919
505- ...expecting res=e229c19e791f2e41
506DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
507<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
508 auth_request_sent == 1
509 lu_result_sent == 0
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]510- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]511 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]512DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]513DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]514DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
515DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
516DVLR SUBSCR(IMSI:901700000010650) received res: e2 29 c1 9e 79 1f 2e 41
517DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
518DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
519DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
520DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
521DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
522DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
523DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
524DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
525DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Neels Hofmeyr4cf4fdd2017-12-14 05:31:27 +0100[diff] [blame^]526DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode: 3=VLR_CIPH_A5_3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]527- sending SecurityModeControl for IMSI:901700000010650
528DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
529DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]530DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]531 cipher_mode_cmd_sent == 1
532 lu_result_sent == 0
533- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
534DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
535DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
536DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
537DIUCS IMSI:901700000010650: tx CommonID 901700000010650
538- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
539DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
540DVLR 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 +0100[diff] [blame]541DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
542DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
543DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
544DVLR GSUP tx: 04010809710000000156f0
545GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
546DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]547 gsup_tx_confirmed == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]548 lu_result_sent == 0
549- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
550<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
551DVLR GSUP rx 17: 10010809710000000156f00804032443f2
552DREF VLR subscr IMSI:901700000010650 usage increases to: 2
553DVLR IMSI:901700000010650 has MSISDN:42342
554DVLR GSUP tx: 12010809710000000156f0
555GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
556DREF VLR subscr MSISDN:42342 usage decreases to: 1
557<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
558 lu_result_sent == 0
559- HLR also sends GSUP _UPDATE_LOCATION_RESULT
560<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
561DVLR GSUP rx 11: 06010809710000000156f0
562DREF VLR subscr MSISDN:42342 usage increases to: 2
563DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
564DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
565DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
566DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
567DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
568DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
569DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
570DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
571DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
572DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
573DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
574DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
575DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
576DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
577DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
578DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
579DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
580DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
581DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
582DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
583DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
584DVLR 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 +0200[diff] [blame]585DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
586DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
587- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
588DREF VLR subscr MSISDN:42342 usage decreases to: 1
589<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
590 lu_result_sent == 1
591- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
592 llist_count(&net->subscr_conns) == 1
593msc_subscr_conn_is_accepted() == false
594 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]595DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
596DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
597DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
598DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
599DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
600DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
601DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x01 (0x9:0x1)
602DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_PDISC_SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]603- even though the TMSI is not acked, we can already find the subscr with it
604DREF VLR subscr MSISDN:42342 usage increases to: 2
605 vsub != NULL == 1
606 strcmp(vsub->imsi, imsi) == 0
607 vsub->tmsi_new == 0x03020100
608 vsub->tmsi == 0xffffffff
609DREF VLR subscr MSISDN:42342 usage decreases to: 1
610- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]611 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]612DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]613DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]614DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
615DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
616DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
617DREF VLR subscr MSISDN:42342 usage increases to: 2
618DVLR 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 +0100[diff] [blame]619DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
620DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
621DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
622DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
623DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
624DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]625DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
626DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
627DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
628DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
629DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
630DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
631DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]632DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
633DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
634DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
635DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
636DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
637DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]638- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]639DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]640DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
641DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]642DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]643DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]644DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]645 iu_release_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]646- LU was successful, and the conn has already been closed
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]647 llist_count(&net->subscr_conns) == 0
648---
649- 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 +0100[diff] [blame]650 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]651 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]652DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]653DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]654DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]655DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]656DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
657DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
658DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]659DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
660DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]661DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]662DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
663DREF VLR subscr MSISDN:42342 usage increases to: 2
664DREF VLR subscr MSISDN:42342 usage increases to: 3
665DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
666DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
667DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
668DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
669DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
670DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
671DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
672- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
673- ...rand=c187a53a5e6b9d573cac7c74451fd46d
674- ...autn=1843a645b98d00005b2d666af46c45d9
675- ...expecting res=7db47cf7f81e4dc7
676DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]677DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]678DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]679 cm_service_result_sent == 0
680 auth_request_sent == 1
681- needs auth, not yet accepted
682msc_subscr_conn_is_accepted() == false
683 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]684DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
685DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
686DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
687DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
688DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
689DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
690DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x01 (0x9:0x1)
691DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_PDISC_SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]692- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]693 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]694DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]695DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]696DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
697DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
698DVLR SUBSCR(MSISDN:42342) received res: 7d b4 7c f7 f8 1e 4d c7
699DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
700DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
701DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
702DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
703DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
704DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
705DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
706DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
707DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
708DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Neels Hofmeyr4cf4fdd2017-12-14 05:31:27 +0100[diff] [blame^]709DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode: 3=VLR_CIPH_A5_3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]710- sending SecurityModeControl for MSISDN:42342
711DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
712DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]713DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]714 cipher_mode_cmd_sent == 1
715 cm_service_result_sent == 0
716- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
717DMM <- SECURITY MODE COMPLETE MSISDN:42342
718DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
719DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
720DIUCS MSISDN:42342: tx CommonID 901700000010650
721- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
722DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
723DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
724DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
725DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
726DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
727DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
728DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
729DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
730DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
731DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
732DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
733DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
734DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
735 cm_service_result_sent == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]736- a USSD request is serviced
737 expecting USSD:
738 Your extension is 42342
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]739 MSC <--RAN_UTRAN_IU-- MS: GSM48_PDISC_NC_SS:0x3b
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]740DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]741DRLL Dispatching 04.08 message GSM48_PDISC_NC_SS:0x3b (0xb:0x3b)
742DMM MSISDN:42342: rx msg GSM48_PDISC_NC_SS:0x3b: received_cm_service_request changes to false
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]743DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
744DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]745DMM USSD: Own number requested
746DMM MSISDN:42342: MSISDN = 42342
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]747DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_UTRAN_IU
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]748- DTAP --RAN_UTRAN_IU--> MS: GSM48_PDISC_NC_SS:0x2a: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]749- DTAP matches expected message
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]750DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
751DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
752DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
753DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]754DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
755DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
756DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
757DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
758DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]759- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]760DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]761DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
762DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]763DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]764DRLL subscr MSISDN:42342: Freeing subscriber connection
765DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]766 iu_release_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]767- all requests serviced, conn has been released
768 llist_count(&net->subscr_conns) == 0
769---
770- an SMS is sent, MS is paged
771DREF VLR subscr MSISDN:42342 usage increases to: 2
772 llist_count(&vsub->cs.requests) == 0
773DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]774DMM Subscriber MSISDN:42342 not paged yet, start paging.
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]775 RAN_UTRAN_IU sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]776 strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]777DREF VLR subscr MSISDN:42342 usage increases to: 4
778 llist_count(&vsub->cs.requests) == 1
779DREF VLR subscr MSISDN:42342 usage decreases to: 3
780 paging_sent == 1
781 paging_stopped == 0
782- the subscriber and its pending request should remain
783DREF VLR subscr MSISDN:42342 usage increases to: 4
784 llist_count(&vsub->cs.requests) == 1
785DREF VLR subscr MSISDN:42342 usage decreases to: 3
786- MS replies with Paging Response, and VLR sends Auth Request with third key
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]787 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]788 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]789DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]790DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]791DRR PAGING RESPONSE: MI(IMSI)=901700000010650
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]792DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]793DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
794DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
795DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]796DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
797DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]798DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]799DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
800DREF VLR subscr MSISDN:42342 usage increases to: 4
801DREF VLR subscr MSISDN:42342 usage increases to: 5
802DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
803DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
804DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
805DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
806DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
807DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
808DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2
809- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
810- ...rand=efa9c29a9742148d5c9070348716e1bb
811- ...autn=f9375e6d41e1000096e7fe4ff1c27e39
812- ...expecting res=706f996719ba609c
813DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]814DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]815DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]816 auth_request_sent == 1
817- needs auth, not yet accepted
818msc_subscr_conn_is_accepted() == false
819 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]820DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
821DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
822DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
823DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
824DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
825DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
826DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x01 (0x9:0x1)
827DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_PDISC_SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]828- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]829 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]830DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]831DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]832DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 706f996719ba609c)
833DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
834DVLR SUBSCR(MSISDN:42342) received res: 70 6f 99 67 19 ba 60 9c
835DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
836DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
837DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
838DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
839DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
840DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
841DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
842DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
843DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
844DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Neels Hofmeyr4cf4fdd2017-12-14 05:31:27 +0100[diff] [blame^]845DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode: 3=VLR_CIPH_A5_3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]846- sending SecurityModeControl for MSISDN:42342
847DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
848DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]849DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]850 cipher_mode_cmd_sent == 1
851 paging_stopped == 0
852- MS sends SecurityModeControl acceptance, VLR accepts and sends SMS
853DMM <- SECURITY MODE COMPLETE MSISDN:42342
854DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
855DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
856DIUCS MSISDN:42342: tx CommonID 901700000010650
857- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
858DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
859DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
860DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
861DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
862DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
863DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]864DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]865DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
866DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
867DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
868DPAG Paging success for MSISDN:42342 (event=0)
869DPAG Calling paging cbfn.
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]870DREF VLR subscr MSISDN:42342 usage increases to: 5
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]871DREF MSISDN:42342: MSC conn use + trans_sms == 2 (0x14)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]872DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_UTRAN_IU
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]873- DTAP --RAN_UTRAN_IU--> MS: GSM48_PDISC_SMS:0x01: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]874- DTAP matches expected message
875DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]876DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
877DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_SMS
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]878 paging_stopped == 1
879- SMS was delivered, no requests pending for subscr
880DREF VLR subscr MSISDN:42342 usage increases to: 5
881 llist_count(&vsub->cs.requests) == 0
882DREF VLR subscr MSISDN:42342 usage decreases to: 4
883- conn is still open to wait for SMS ack dance
884 llist_count(&net->subscr_conns) == 1
885- MS replies with CP-ACK for received SMS
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]886 MSC <--RAN_UTRAN_IU-- MS: GSM48_PDISC_SMS:0x04
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]887DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]888DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x04 (0x9:0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]889DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
890DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
891DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
892DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_SMS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]893DREF MSISDN:42342: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]894 llist_count(&net->subscr_conns) == 1
895- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]896 MSC <--RAN_UTRAN_IU-- MS: GSM48_PDISC_SMS:0x01
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]897DREF MSISDN:42342: MSC conn use + dtap == 3 (0x16)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]898DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x01 (0x9:0x1)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]899DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
900DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]901- DTAP --RAN_UTRAN_IU--> MS: GSM48_PDISC_SMS:0x04: 0904
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]902- DTAP matches expected message
903DREF VLR subscr MSISDN:42342 usage decreases to: 3
904DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]905DREF MSISDN:42342: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]906DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
907DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
908DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
909DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]910DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
911DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
912DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
913DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
914DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]915- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]916DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]917DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
918DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]919DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]920DRLL subscr MSISDN:42342: Freeing subscriber connection
921DREF VLR subscr MSISDN:42342 usage decreases to: 1
922 dtap_tx_confirmed == 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]923 iu_release_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]924- SMS is done, conn is gone
925 llist_count(&net->subscr_conns) == 0
926---
927- subscriber detaches
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]928 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]929 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]930DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]931DRLL Dispatching 04.08 message GSM48_MT_MM_IMSI_DETACH_IND (0x5:0x1)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]932DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
933DREF VLR subscr MSISDN:42342 usage increases to: 2
934DMM IMSI DETACH for MSISDN:42342
935DREF VLR subscr MSISDN:42342 usage decreases to: 1
936DREF VLR subscr MSISDN:42342 usage decreases to: 0
937DREF freeing VLR subscr MSISDN:42342
938DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]939- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]940DREF unknown: MSC conn use - compl_l3 == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]941DRLL Freeing subscriber connection with NULL subscriber
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]942 iu_release_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]943 llist_count(&net->subscr_conns) == 0
944===== test_umts_authen_utran: SUCCESS
945
946full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]947talloc_total_blocks(tall_bsc_ctx) == 9
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]948
949===== test_umts_authen_resync_geran
950- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]951 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]952 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]953DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]954DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]955DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]956DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
957DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
958DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]959DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]960DMM LU/new-LAC: 0/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]961DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
962DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
963DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth (no Ciph)
964DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
965DREF VLR subscr unknown usage increases to: 1
966DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
967DVLR New subscr, IMSI: 901700000010650
968DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]969DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]970DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
971DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
972DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
973DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
974DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
975DVLR GSUP tx: 08010809710000000156f0
976GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
977DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]978DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]979DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]980 lu_result_sent == 0
981- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
982<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
983DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
984DREF VLR subscr IMSI:901700000010650 usage increases to: 2
985DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
986DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples
987DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
988DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
989- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
990- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
991- ...autn=8704f5ba55f30000d2ee44b22c8ea919
992- ...expecting res=e229c19e791f2e41
993DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
994<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
995 auth_request_sent == 1
996 lu_result_sent == 0
997- MS sends Authen Failure with Resync cause, VLR sends GSUP to HLR to resync
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]998 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_FAIL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]999DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1000DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_FAIL (0x5:0x1c)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1001DMM IMSI:901700000010650: MM R99 AUTHENTICATION SYNCH (AUTS = 979498b1f72d3e28c59fa2e72f9c)
1002DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_FAIL
1003DVLR GSUP tx: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
1004GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
1005DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1006DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1007DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1008 gsup_tx_confirmed == 1
1009 auth_request_sent == 0
1010 lu_result_sent == 0
1011- HLR replies with new tuples
1012<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
1013DVLR GSUP rx 211: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
1014DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1015DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1016DVLR SUBSCR(IMSI:901700000010650) Received 2 auth tuples
1017DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: state_chg to VLR_SUB_AS_WAIT_RESP_RESYNC
1018DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: got auth tuple: use_count=1 key_seq=0
1019- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1020- ...rand=0f1feb1623e1bf626334e37ec448ac18
1021- ...autn=02a83f62e9470000660d51afc75f169d
1022- ...expecting res=1df5f0b4f22b696e
1023DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1024<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1025 auth_request_sent == 1
1026 lu_result_sent == 0
1027- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1028 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1029DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1030DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1031DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = 1df5f0b4f22b696e)
1032DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Received Event VLR_AUTH_E_MS_AUTH_RESP
1033DVLR SUBSCR(IMSI:901700000010650) received res: 1d f5 f0 b4 f2 2b 69 6e
1034DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
1035DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Authentication terminating with result VLR_AUTH_RES_PASSED
1036DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: state_chg to VLR_SUB_AS_AUTHENTICATED
1037DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1038DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
1039DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1040DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1041DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1042DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1043DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
1044DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
1045DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1046DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1047DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1048DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1049DVLR GSUP tx: 04010809710000000156f0
1050GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
1051DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1052DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1053DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1054 gsup_tx_confirmed == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1055 lu_result_sent == 0
1056- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1057<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1058DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1059DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1060DVLR IMSI:901700000010650 has MSISDN:42342
1061DVLR GSUP tx: 12010809710000000156f0
1062GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1063DREF VLR subscr MSISDN:42342 usage decreases to: 1
1064<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1065 lu_result_sent == 0
1066- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1067<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1068DVLR GSUP rx 11: 06010809710000000156f0
1069DREF VLR subscr MSISDN:42342 usage increases to: 2
1070DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1071DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1072DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1073DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1074DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1075DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1076DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1077DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1078DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1079DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1080DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1081DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1082DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1083DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1084DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
1085DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1086DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1087DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1088DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
1089DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1090DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1091DVLR 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 +0200[diff] [blame]1092DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1093DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1094- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
1095DREF VLR subscr MSISDN:42342 usage decreases to: 1
1096<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1097 lu_result_sent == 1
1098- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1099 llist_count(&net->subscr_conns) == 1
1100msc_subscr_conn_is_accepted() == false
1101 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1102DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1103DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1104DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1105DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
1106DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1107DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
1108DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x01 (0x9:0x1)
1109DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_PDISC_SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1110- even though the TMSI is not acked, we can already find the subscr with it
1111DREF VLR subscr MSISDN:42342 usage increases to: 2
1112 vsub != NULL == 1
1113 strcmp(vsub->imsi, imsi) == 0
1114 vsub->tmsi_new == 0x03020100
1115 vsub->tmsi == 0xffffffff
1116DREF VLR subscr MSISDN:42342 usage decreases to: 1
1117- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1118 MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1119DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1120DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1121DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
1122DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1123DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1124DREF VLR subscr MSISDN:42342 usage increases to: 2
1125DVLR 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 +0100[diff] [blame]1126DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1127DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1128DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1129DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1130DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1131DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1132DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1133DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1134DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1135DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1136DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
1137DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1138DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1139DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1140DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1141DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1142DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1143DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1144DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]1145- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1146DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1147DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1148DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1149DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1150DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1151DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]1152 bssap_clear_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1153- LU was successful, and the conn has already been closed
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1154 llist_count(&net->subscr_conns) == 0
1155DREF freeing VLR subscr MSISDN:42342
1156===== test_umts_authen_resync_geran: SUCCESS
1157
1158full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1159talloc_total_blocks(tall_bsc_ctx) == 9
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1160
1161===== test_umts_authen_resync_utran
1162- Location Update request causes a GSUP Send Auth Info request to HLR
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1163 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1164 new conn
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1165DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1166DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1167DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1168DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1169DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1170DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1171DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
Neels Hofmeyr8a656eb2017-11-22 02:55:52 +0100[diff] [blame]1172DMM LU/new-LAC: 0/23
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1173DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1174DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1175DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1176DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1177DREF VLR subscr unknown usage increases to: 1
1178DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1179DVLR New subscr, IMSI: 901700000010650
1180DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr54a706c2017-07-18 15:39:27 +0200[diff] [blame]1181DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1182DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1183DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1184DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1185DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1186DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1187DVLR GSUP tx: 08010809710000000156f0
1188GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1189DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1190DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1191DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1192 lu_result_sent == 0
1193- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1194<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
1195DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
1196DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1197DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1198DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples
1199DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
1200DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
1201- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1202- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1203- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1204- ...expecting res=e229c19e791f2e41
1205DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1206<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1207 auth_request_sent == 1
1208 lu_result_sent == 0
1209- MS sends Authen Failure with Resync cause, VLR sends GSUP to HLR to resync
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1210 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_FAIL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1211DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1212DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_FAIL (0x5:0x1c)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1213DMM IMSI:901700000010650: MM R99 AUTHENTICATION SYNCH (AUTS = 979498b1f72d3e28c59fa2e72f9c)
1214DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_FAIL
1215DVLR GSUP tx: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
1216GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
1217DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1218DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1219DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1220 gsup_tx_confirmed == 1
1221 auth_request_sent == 0
1222 lu_result_sent == 0
1223- HLR replies with new tuples
1224<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
1225DVLR GSUP rx 211: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
1226DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1227DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1228DVLR SUBSCR(IMSI:901700000010650) Received 2 auth tuples
1229DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: state_chg to VLR_SUB_AS_WAIT_RESP_RESYNC
1230DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: got auth tuple: use_count=1 key_seq=0
1231- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1232- ...rand=0f1feb1623e1bf626334e37ec448ac18
1233- ...autn=02a83f62e9470000660d51afc75f169d
1234- ...expecting res=1df5f0b4f22b696e
1235DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1236<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1237 auth_request_sent == 1
1238 lu_result_sent == 0
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1239- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1240 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1241DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1242DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1243DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = 1df5f0b4f22b696e)
1244DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Received Event VLR_AUTH_E_MS_AUTH_RESP
1245DVLR SUBSCR(IMSI:901700000010650) received res: 1d f5 f0 b4 f2 2b 69 6e
1246DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
1247DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Authentication terminating with result VLR_AUTH_RES_PASSED
1248DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: state_chg to VLR_SUB_AS_AUTHENTICATED
1249DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1250DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
1251DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1252DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1253DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1254DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Neels Hofmeyr4cf4fdd2017-12-14 05:31:27 +0100[diff] [blame^]1255DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode: 3=VLR_CIPH_A5_3
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1256- sending SecurityModeControl for IMSI:901700000010650
1257DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
1258DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1259DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1260 cipher_mode_cmd_sent == 1
1261 lu_result_sent == 0
1262- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
1263DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
1264DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1265DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
1266DIUCS IMSI:901700000010650: tx CommonID 901700000010650
1267- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
1268DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1269DVLR 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 +0100[diff] [blame]1270DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1271DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1272DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1273DVLR GSUP tx: 04010809710000000156f0
1274GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
1275DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1276 gsup_tx_confirmed == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1277 lu_result_sent == 0
1278- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1279<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1280DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1281DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1282DVLR IMSI:901700000010650 has MSISDN:42342
1283DVLR GSUP tx: 12010809710000000156f0
1284GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1285DREF VLR subscr MSISDN:42342 usage decreases to: 1
1286<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1287 lu_result_sent == 0
1288- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1289<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1290DVLR GSUP rx 11: 06010809710000000156f0
1291DREF VLR subscr MSISDN:42342 usage increases to: 2
1292DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1293DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1294DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1295DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1296DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1297DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1298DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1299DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1300DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1301DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1302DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1303DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1304DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1305DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1306DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
1307DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1308DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1309DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1310DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
1311DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1312DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1313DVLR 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 +0200[diff] [blame]1314DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1315DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1316- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
1317DREF VLR subscr MSISDN:42342 usage decreases to: 1
1318<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1319 lu_result_sent == 1
1320- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1321 llist_count(&net->subscr_conns) == 1
1322msc_subscr_conn_is_accepted() == false
1323 requests shall be thwarted
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1324DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1325DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_CC_SETUP
1326DRLL Dispatching 04.08 message unknown 0x33 (0x5:0x33)
1327DRLL subscr MSISDN:42342: Message not permitted for initial conn: unknown 0x33
1328DRLL Dispatching 04.08 message GSM48_MT_RR_SYSINFO_1 (0x6:0x19)
1329DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_MT_RR_SYSINFO_1
1330DRLL Dispatching 04.08 message GSM48_PDISC_SMS:0x01 (0x9:0x1)
1331DRLL subscr MSISDN:42342: Message not permitted for initial conn: GSM48_PDISC_SMS:0x01
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1332- even though the TMSI is not acked, we can already find the subscr with it
1333DREF VLR subscr MSISDN:42342 usage increases to: 2
1334 vsub != NULL == 1
1335 strcmp(vsub->imsi, imsi) == 0
1336 vsub->tmsi_new == 0x03020100
1337 vsub->tmsi == 0xffffffff
1338DREF VLR subscr MSISDN:42342 usage decreases to: 1
1339- MS sends TMSI Realloc Complete
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1340 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1341DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr78ada642017-03-10 02:15:20 +0100[diff] [blame]1342DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1343DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
1344DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1345DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1346DREF VLR subscr MSISDN:42342 usage increases to: 2
1347DVLR 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 +0100[diff] [blame]1348DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1349DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1350DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1351DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1352DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1353DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1354DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
1355DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
1356DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1357DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
1358DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
1359DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1360DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1361DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1362DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1363DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1364DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1365DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1366DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1367- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1368DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1369DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1370DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr6166f292017-11-22 14:33:12 +0100[diff] [blame]1371DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1372DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1373DREF VLR subscr MSISDN:42342 usage decreases to: 1
Philipp Maierfbf66102017-04-09 12:32:51 +0200[diff] [blame]1374 iu_release_sent == 1
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1375- LU was successful, and the conn has already been closed
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1376 llist_count(&net->subscr_conns) == 0
1377DREF freeing VLR subscr MSISDN:42342
1378===== test_umts_authen_resync_utran: SUCCESS
1379
1380full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr84da6b12016-05-20 21:59:55 +0200[diff] [blame]1381talloc_total_blocks(tall_bsc_ctx) == 9
Neels Hofmeyr6a29d322017-01-25 15:04:16 +0100[diff] [blame]1382
1383full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1384talloc_total_blocks(tall_bsc_ctx) == 9
1385