Blame - tests/msc_vlr/msc_vlr_test_umts_authen.err - osmo-msc

blob: 8a45167f9e0528192822e7bf64fd55cfbdf7df3d [file] [log] [blame]

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