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

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