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

blob: 7dca53f7bd299055da9fcb2534169b01cddf275a [file] [log] [blame]

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