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

blob: 07f5e55c40c920ad68050994d0c77f475f10fb94 [file] [log] [blame]

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