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

blob: 8e07154e8c9a9c7569ddfb715a135d73bb04bcc6 [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	12e17be	2018-03-12 23:59:37 +0100	[diff] [blame^]	1281	DCC (ti 00 sub MSISDN:46071 callref 40000001) New transaction
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1282	DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1283	DREF MSISDN:46071: MSC conn use + trans_sms == 3 (0x15)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1284	DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1285	- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1286	- DTAP matches expected message
				1287	DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1288	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]	1289	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]	1290	DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1291	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]	1292	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]	1293	DREF MSISDN:46071: MSC conn use - compl_l3 == 2 (0x14)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1294	dtap_tx_confirmed == 1
				1295	paging_stopped == 1
				1296	- conn is still open to wait for SMS ack dance
				1297	llist_count(&net->subscr_conns) == 1
				1298	---
				1299	- MS sends erratic LU Request, which is dropped silently
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1300	MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1301	DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1302	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]	1303	DMM 901700000004620: Error: connection already in use
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1304	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]	1305	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]	1306	DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1307	lu_result_sent == 0
				1308	llist_count(&net->subscr_conns) == 1
				1309	- MS replies with CP-ACK for received SMS
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1310	MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1311	DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1312	DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1313	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
				1314	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
				1315	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]	1316	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]	1317	DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1318	llist_count(&net->subscr_conns) == 1
				1319	- 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]	1320	MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1321	DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1322	DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1323	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
				1324	DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1325	- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1326	- DTAP matches expected message
				1327	DREF VLR subscr MSISDN:46071 usage decreases to: 3
				1328	DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1329	DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1330	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
				1331	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
				1332	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
				1333	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]	1334	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				1335	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
				1336	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
				1337	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
				1338	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]	1339	- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1340	DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1341	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
				1342	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1343	DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1344	DRLL subscr MSISDN:46071: Freeing subscriber connection
				1345	DREF VLR subscr MSISDN:46071 usage decreases to: 1
				1346	dtap_tx_confirmed == 1
Philipp Maier	fbf6610	2017-04-09 12:32:51 +0200	[diff] [blame]	1347	bssap_clear_sent == 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1348	- SMS is done
				1349	llist_count(&net->subscr_conns) == 0
				1350	DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyr	dfdc61d	2018-03-02 00:40:58 +0100	[diff] [blame]	1351	===== test_reject_lu_during_paging_resp: SUCCESS
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1352
				1353	full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte	2346619	2018-02-14 00:19:06 +0100	[diff] [blame]	1354	talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1355
Neels Hofmeyr	dfdc61d	2018-03-02 00:40:58 +0100	[diff] [blame]	1356	===== test_accept_cm_during_paging_resp
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1357	---
				1358	- Subscriber does a normal LU
				1359	- Location Update Request
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1360	MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1361	new conn
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1362	DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1363	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]	1364	DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1365	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
				1366	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				1367	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]	1368	DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr	8a656eb	2017-11-22 02:55:52 +0100	[diff] [blame]	1369	DMM LU/new-LAC: 1/23
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1370	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
				1371	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
				1372	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
				1373	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
				1374	DREF VLR subscr unknown usage increases to: 1
				1375	DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
				1376	DVLR New subscr, IMSI: 901700000004620
				1377	DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr	54a706c	2017-07-18 15:39:27 +0200	[diff] [blame]	1378	DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1379	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
				1380	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
				1381	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
				1382	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
				1383	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
				1384	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
				1385	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
				1386	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
				1387	DVLR GSUP tx: 04010809710000004026f0
				1388	GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
				1389	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]	1390	DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1391	DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1392	lu_result_sent == 0
				1393	llist_count(&net->subscr_conns) == 1
				1394	- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
				1395	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
				1396	DVLR GSUP rx 17: 10010809710000004026f00804036470f1
				1397	DREF VLR subscr IMSI:901700000004620 usage increases to: 2
				1398	DVLR IMSI:901700000004620 has MSISDN:46071
Max	a263bb2	2017-12-27 13:23:44 +0100	[diff] [blame]	1399	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]	1400	DVLR GSUP tx: 12010809710000004026f0
				1401	GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
				1402	DREF VLR subscr MSISDN:46071 usage decreases to: 1
				1403	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
				1404	lu_result_sent == 0
				1405	- HLR also sends GSUP _UPDATE_LOCATION_RESULT
				1406	<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
				1407	DVLR GSUP rx 11: 06010809710000004026f0
				1408	DREF VLR subscr MSISDN:46071 usage increases to: 2
				1409	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
				1410	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
				1411	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
				1412	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				1413	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
				1414	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
				1415	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
				1416	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
				1417	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
				1418	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
				1419	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
				1420	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
				1421	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
				1422	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
				1423	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
				1424	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
				1425	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
				1426	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				1427	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
				1428	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
				1429	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
				1430	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
				1431	- sending LU Accept for MSISDN:46071
				1432	DREF VLR subscr MSISDN:46071 usage increases to: 3
				1433	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
				1434	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
				1435	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				1436	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
				1437	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
				1438	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
				1439	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]	1440	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				1441	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
				1442	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				1443	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				1444	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
				1445	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
				1446	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]	1447	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				1448	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
				1449	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
				1450	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
				1451	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
				1452	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]	1453	- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1454	DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1455	DRLL subscr MSISDN:46071: Freeing subscriber connection
				1456	DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1457	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
				1458	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1459	DREF VLR subscr MSISDN:46071 usage decreases to: 1
				1460	<-- 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]	1461	bssap_clear_sent == 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1462	- LU was successful, and the conn has already been closed
				1463	lu_result_sent == 1
				1464	llist_count(&net->subscr_conns) == 0
				1465	---
				1466	- an SMS is sent, MS is paged
				1467	DREF VLR subscr MSISDN:46071 usage increases to: 2
				1468	llist_count(&vsub->cs.requests) == 0
				1469	DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1470	DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr	8a656eb	2017-11-22 02:55:52 +0100	[diff] [blame]	1471	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]	1472	strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1473	DREF VLR subscr MSISDN:46071 usage increases to: 4
				1474	llist_count(&vsub->cs.requests) == 1
				1475	DREF VLR subscr MSISDN:46071 usage decreases to: 3
				1476	paging_sent == 1
				1477	paging_stopped == 0
				1478	- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1479	MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1480	new conn
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1481	DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1482	DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1483	DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1484	DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1485	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
				1486	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				1487	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]	1488	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
				1489	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
				1490	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
				1491	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
				1492	DREF VLR subscr MSISDN:46071 usage increases to: 4
				1493	DREF VLR subscr MSISDN:46071 usage increases to: 5
				1494	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
				1495	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
				1496	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
				1497	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
				1498	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
				1499	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
				1500	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
				1501	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
				1502	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
				1503	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]	1504	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				1505	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
				1506	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				1507	DPAG Paging success for MSISDN:46071 (event=0)
				1508	DPAG Calling paging cbfn.
Neels Hofmeyr	12e17be	2018-03-12 23:59:37 +0100	[diff] [blame^]	1509	DCC (ti 00 sub MSISDN:46071 callref 40000002) New transaction
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1510	DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1511	DREF MSISDN:46071: MSC conn use + trans_sms == 3 (0x15)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1512	DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1513	- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1514	- DTAP matches expected message
				1515	DREF VLR subscr MSISDN:46071 usage decreases to: 5
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1516	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]	1517	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]	1518	DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1519	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]	1520	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]	1521	DREF MSISDN:46071: MSC conn use - compl_l3 == 2 (0x14)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1522	dtap_tx_confirmed == 1
				1523	paging_stopped == 1
				1524	- conn is still open to wait for SMS ack dance
				1525	llist_count(&net->subscr_conns) == 1
				1526	---
				1527	- CM Service Request during open connection is accepted
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1528	MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_CM_SERV_REQ
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1529	DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1530	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]	1531	DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000004620
				1532	DMM MSISDN:46071: re-using already accepted connection
				1533	- sending CM Service Accept for MSISDN:46071
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1534	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				1535	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]	1536	DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1537	cm_service_result_sent == 1
				1538	llist_count(&net->subscr_conns) == 1
				1539	g_conn->received_cm_service_request == 1
				1540	- MS replies with CP-ACK for received SMS
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1541	MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1542	DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1543	DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1544	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
				1545	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
				1546	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
				1547	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]	1548	DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1549	llist_count(&net->subscr_conns) == 1
				1550	- 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]	1551	MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1552	DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1553	DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1554	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
				1555	DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1556	- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1557	- DTAP matches expected message
				1558	DREF VLR subscr MSISDN:46071 usage decreases to: 3
				1559	DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1560	DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1561	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
				1562	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]	1563	DREF MSISDN:46071: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1564	dtap_tx_confirmed == 1
				1565	- SMS is done
				1566	llist_count(&net->subscr_conns) == 1
				1567	---
				1568	- subscriber detaches
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1569	MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_IMSI_DETACH_IND
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1570	DREF MSISDN:46071: MSC conn use + dtap == 2 (0x6)
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1571	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]	1572	DMM IMSI DETACH INDICATION: MI(IMSI)=901700000004620
				1573	DREF VLR subscr MSISDN:46071 usage increases to: 3
				1574	DMM IMSI DETACH for MSISDN:46071
				1575	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_ERROR)
				1576	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
				1577	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
				1578	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1579	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_CN_CLOSE
				1580	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
				1581	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]	1582	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]	1583	- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1584	DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1585	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
				1586	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1587	DREF VLR subscr MSISDN:46071 usage decreases to: 2
				1588	DREF VLR subscr MSISDN:46071 usage decreases to: 1
				1589	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]	1590	DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1591	DRLL subscr MSISDN:46071: Freeing subscriber connection
				1592	DREF VLR subscr MSISDN:46071 usage decreases to: 0
				1593	DREF freeing VLR subscr MSISDN:46071
Philipp Maier	fbf6610	2017-04-09 12:32:51 +0200	[diff] [blame]	1594	bssap_clear_sent == 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1595	llist_count(&net->subscr_conns) == 0
Neels Hofmeyr	dfdc61d	2018-03-02 00:40:58 +0100	[diff] [blame]	1596	===== test_accept_cm_during_paging_resp: SUCCESS
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1597
				1598	full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte	2346619	2018-02-14 00:19:06 +0100	[diff] [blame]	1599	talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1600
Neels Hofmeyr	dfdc61d	2018-03-02 00:40:58 +0100	[diff] [blame]	1601	===== test_reject_paging_resp_during_paging_resp
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1602	---
				1603	- Subscriber does a normal LU
				1604	- Location Update Request
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1605	MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1606	new conn
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1607	DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1608	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]	1609	DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1610	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
				1611	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				1612	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]	1613	DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH
Neels Hofmeyr	8a656eb	2017-11-22 02:55:52 +0100	[diff] [blame]	1614	DMM LU/new-LAC: 1/23
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1615	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Allocated
				1616	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000004620)
				1617	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN (no Auth)
				1618	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
				1619	DREF VLR subscr unknown usage increases to: 1
				1620	DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620
				1621	DVLR New subscr, IMSI: 901700000004620
				1622	DREF VLR subscr IMSI:901700000004620 usage increases to: 2
Neels Hofmeyr	54a706c	2017-07-18 15:39:27 +0200	[diff] [blame]	1623	DREF VLR subscr IMSI:901700000004620 usage decreases to: 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1624	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
				1625	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_auth()
				1626	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_post_ciph()
				1627	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node_4()
				1628	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
				1629	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Allocated
				1630	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
				1631	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
				1632	DVLR GSUP tx: 04010809710000004026f0
				1633	GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000004026f0
				1634	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]	1635	DMM IMSI:901700000004620: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1636	DREF IMSI:901700000004620: MSC conn use - compl_l3 == 1 (0x4)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1637	lu_result_sent == 0
				1638	llist_count(&net->subscr_conns) == 1
				1639	- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
				1640	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000004026f00804036470f1
				1641	DVLR GSUP rx 17: 10010809710000004026f00804036470f1
				1642	DREF VLR subscr IMSI:901700000004620 usage increases to: 2
				1643	DVLR IMSI:901700000004620 has MSISDN:46071
Max	a263bb2	2017-12-27 13:23:44 +0100	[diff] [blame]	1644	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]	1645	DVLR GSUP tx: 12010809710000004026f0
				1646	GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000004026f0
				1647	DREF VLR subscr MSISDN:46071 usage decreases to: 1
				1648	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
				1649	lu_result_sent == 0
				1650	- HLR also sends GSUP _UPDATE_LOCATION_RESULT
				1651	<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000004026f0
				1652	DVLR GSUP rx 11: 06010809710000004026f0
				1653	DREF VLR subscr MSISDN:46071 usage increases to: 2
				1654	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
				1655	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
				1656	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
				1657	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				1658	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
				1659	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Freeing instance
				1660	DVLR upd_hlr_vlr_fsm(901700000004620){UPD_HLR_VLR_S_DONE}: Deallocated
				1661	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
				1662	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
				1663	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Allocated
				1664	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000004620)
				1665	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
				1666	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
				1667	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Allocated
				1668	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000004620)
				1669	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
				1670	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
				1671	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				1672	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000004620)
				1673	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Freeing instance
				1674	DVLR sub_pres_vlr_fsm(901700000004620){SUB_PRES_VLR_S_DONE}: Deallocated
				1675	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
				1676	- sending LU Accept for MSISDN:46071
				1677	DREF VLR subscr MSISDN:46071 usage increases to: 3
				1678	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_DONE
				1679	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
				1680	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				1681	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000004620)
				1682	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Freeing instance
				1683	DVLR lu_compl_vlr_fsm(901700000004620){LU_COMPL_VLR_S_DONE}: Deallocated
				1684	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]	1685	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				1686	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
				1687	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				1688	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				1689	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
				1690	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
				1691	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]	1692	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				1693	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
				1694	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
				1695	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Freeing instance
				1696	DVLR vlr_lu_fsm(901700000004620){VLR_ULA_S_DONE}: Deallocated
				1697	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]	1698	- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1699	DREF MSISDN:46071: MSC conn use - fsm == 0 (0x0)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1700	DRLL subscr MSISDN:46071: Freeing subscriber connection
				1701	DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1702	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
				1703	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1704	DREF VLR subscr MSISDN:46071 usage decreases to: 1
				1705	<-- 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]	1706	bssap_clear_sent == 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1707	- LU was successful, and the conn has already been closed
				1708	lu_result_sent == 1
				1709	llist_count(&net->subscr_conns) == 0
				1710	---
				1711	- an SMS is sent, MS is paged
				1712	DREF VLR subscr MSISDN:46071 usage increases to: 2
				1713	llist_count(&vsub->cs.requests) == 0
				1714	DREF VLR subscr MSISDN:46071 usage increases to: 3
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1715	DMM Subscriber MSISDN:46071 not paged yet, start paging.
Neels Hofmeyr	8a656eb	2017-11-22 02:55:52 +0100	[diff] [blame]	1716	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]	1717	strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1718	DREF VLR subscr MSISDN:46071 usage increases to: 4
				1719	llist_count(&vsub->cs.requests) == 1
				1720	DREF VLR subscr MSISDN:46071 usage decreases to: 3
				1721	paging_sent == 1
				1722	paging_stopped == 0
				1723	- MS replies with Paging Response, we deliver the SMS
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1724	MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1725	new conn
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1726	DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1727	DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1728	DRR PAGING RESPONSE: MI(IMSI)=901700000004620
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1729	DREF unknown: MSC conn use + fsm == 2 (0x5)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1730	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Allocated
				1731	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				1732	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]	1733	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Allocated
				1734	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000004620)
				1735	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: rev=GSM net=GERAN (no Auth)
				1736	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
				1737	DREF VLR subscr MSISDN:46071 usage increases to: 4
				1738	DREF VLR subscr MSISDN:46071 usage increases to: 5
				1739	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
				1740	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2()
				1741	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_ciph()
				1742	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_node2_post_vlr()
				1743	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_pres()
				1744	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_trace()
				1745	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: _proc_arq_vlr_post_imei()
				1746	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
				1747	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_DONE
				1748	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]	1749	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				1750	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
				1751	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				1752	DPAG Paging success for MSISDN:46071 (event=0)
				1753	DPAG Calling paging cbfn.
Neels Hofmeyr	12e17be	2018-03-12 23:59:37 +0100	[diff] [blame^]	1754	DCC (ti 00 sub MSISDN:46071 callref 40000003) New transaction
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1755	DREF VLR subscr MSISDN:46071 usage increases to: 6
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1756	DREF MSISDN:46071: MSC conn use + trans_sms == 3 (0x15)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1757	DMSC msc_tx 91 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1758	- DTAP --RAN_GERAN_A--> MS: SMS:0x01: 09015801000791447758100650004c0005806470f1000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1759	- DTAP matches expected message
				1760	DREF VLR subscr MSISDN:46071 usage decreases to: 5
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	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1763	DREF VLR subscr MSISDN:46071 usage decreases to: 4
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1764	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]	1765	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]	1766	DREF MSISDN:46071: MSC conn use - compl_l3 == 2 (0x14)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1767	dtap_tx_confirmed == 1
				1768	paging_stopped == 1
				1769	- conn is still open to wait for SMS ack dance
				1770	llist_count(&net->subscr_conns) == 1
				1771	---
				1772	- MS sends another erratic Paging Response which is dropped silently
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1773	MSC <--RAN_GERAN_A-- MS: GSM48_MT_RR_PAG_RESP
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1774	DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Neels Hofmeyr	78ada64	2017-03-10 02:15:20 +0100	[diff] [blame]	1775	DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1776	DRR PAGING RESPONSE: MI(IMSI)=901700000004620
				1777	DMM 901700000004620: Error: connection already in use
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1778	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]	1779	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]	1780	DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1781	- MS replies with CP-ACK for received SMS
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1782	MSC <--RAN_GERAN_A-- MS: SMS:0x04
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1783	DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1784	DRLL Dispatching 04.08 message SMS:0x04 (0x9:0x4)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1785	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
				1786	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
				1787	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]	1788	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]	1789	DREF MSISDN:46071: MSC conn use - dtap == 2 (0x14)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1790	llist_count(&net->subscr_conns) == 1
				1791	- 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]	1792	MSC <--RAN_GERAN_A-- MS: SMS:0x01
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1793	DREF MSISDN:46071: MSC conn use + dtap == 3 (0x16)
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1794	DRLL Dispatching 04.08 message SMS:0x01 (0x9:0x1)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1795	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
				1796	DMSC msc_tx 2 bytes to MSISDN:46071 via RAN_GERAN_A
Harald Welte	80315ef	2018-01-24 22:53:00 +0100	[diff] [blame]	1797	- DTAP --RAN_GERAN_A--> MS: SMS:0x04: 0904
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1798	- DTAP matches expected message
				1799	DREF VLR subscr MSISDN:46071 usage decreases to: 3
				1800	DREF VLR subscr MSISDN:46071 usage decreases to: 2
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1801	DREF MSISDN:46071: MSC conn use - trans_sms == 2 (0x6)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1802	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
				1803	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
				1804	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
				1805	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]	1806	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				1807	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000004620)
				1808	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Freeing instance
				1809	DVLR Process_Access_Request_VLR(901700000004620){PR_ARQ_S_DONE}: Deallocated
				1810	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]	1811	- BSSAP Clear --RAN_GERAN_A--> MS
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1812	DREF MSISDN:46071: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame]	1813	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance
				1814	DMM Subscr_Conn(901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6166f29	2017-11-22 14:33:12 +0100	[diff] [blame]	1815	DREF MSISDN:46071: MSC conn use - dtap == 0 (0x0)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1816	DRLL subscr MSISDN:46071: Freeing subscriber connection
				1817	DREF VLR subscr MSISDN:46071 usage decreases to: 1
				1818	dtap_tx_confirmed == 1
Philipp Maier	fbf6610	2017-04-09 12:32:51 +0200	[diff] [blame]	1819	bssap_clear_sent == 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1820	- SMS is done
				1821	llist_count(&net->subscr_conns) == 0
				1822	DREF freeing VLR subscr MSISDN:46071
Neels Hofmeyr	dfdc61d	2018-03-02 00:40:58 +0100	[diff] [blame]	1823	===== test_reject_paging_resp_during_paging_resp: SUCCESS
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
				1828	full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Harald Welte	2346619	2018-02-14 00:19:06 +0100	[diff] [blame]	1829	talloc_total_blocks(tall_bsc_ctx) == 7
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1830