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

blob: 66f40ce1e8516f1a7a692899a1137e9fc30b6ee9 [file] [log] [blame]

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