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

blob: bcb6e31f0ff89a021230a5fec5f82a45ba8fa543 [file] [log] [blame]

Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1	===== test_umts_authen_geran
				2	- Location Update request causes a GSUP Send Auth Info request to HLR
				3	rx from MS: pdisc=0x05 msg_type=0x08
				4	new conn
				5	DREF unknown: MSC conn use + 1 == 1
				6	DRLL Dispatching 04.08 message, pdisc=5
				7	DREF unknown: MSC conn use + 1 == 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	8	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
				9	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				10	DMM Subscr_Conn(901700000010650){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)=901700000010650 type=NORMAL
				12	DMM LU/new-LAC: 0/0
				13	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
				14	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
				15	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth (no Ciph)
				16	DVLR vlr_lu_fsm(901700000010650){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=901700000010650 id=901700000010650
				19	DVLR New subscr, IMSI: 901700000010650
				20	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr	54a706c	2017-07-18 15:39:27 +0200	[diff] [blame]	21	DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	22	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
				23	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
				24	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
				25	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
				26	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
				27	DVLR GSUP tx: 08010809710000000156f0
				28	GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
				29	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	30	DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	31	DREF IMSI:901700000010650: MSC conn use - 1 == 1
				32	lu_result_sent == 0
				33	- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
				34	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
				35	DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
				36	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
				37	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
				38	DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
				39	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
				40	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
				41	- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
				42	- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
				43	- ...autn=8704f5ba55f30000d2ee44b22c8ea919
				44	- ...expecting res=e229c19e791f2e41
				45	DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
				46	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
				47	auth_request_sent == 1
				48	lu_result_sent == 0
				49	- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
				50	rx from MS: pdisc=0x05 msg_type=0x54
				51	DREF IMSI:901700000010650: MSC conn use + 1 == 2
				52	DRLL Dispatching 04.08 message, pdisc=5
				53	DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
				54	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
				55	DVLR SUBSCR(IMSI:901700000010650) received res: e2 29 c1 9e 79 1f 2e 41
				56	DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
				57	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
				58	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
				59	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				60	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
				61	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
				62	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
				63	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
				64	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
				65	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
				66	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
				67	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
				68	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
				69	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
				70	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
				71	DVLR GSUP tx: 04010809710000000156f0
				72	GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
				73	DVLR upd_hlr_vlr_fsm(901700000010650){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^]	74	DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	75	DREF IMSI:901700000010650: MSC conn use - 1 == 1
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	76	gsup_tx_confirmed == 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	77	lu_result_sent == 0
				78	- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
				79	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
				80	DVLR GSUP rx 17: 10010809710000000156f00804032443f2
				81	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
				82	DVLR IMSI:901700000010650 has MSISDN:42342
				83	DVLR GSUP tx: 12010809710000000156f0
				84	GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
				85	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				86	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
				87	lu_result_sent == 0
				88	- HLR also sends GSUP _UPDATE_LOCATION_RESULT
				89	<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
				90	DVLR GSUP rx 11: 06010809710000000156f0
				91	DREF VLR subscr MSISDN:42342 usage increases to: 2
				92	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
				93	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
				94	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
				95	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				96	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
				97	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
				98	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
				99	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
				100	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
				101	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
				102	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
				103	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
				104	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
				105	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
				106	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
				107	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
				108	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
				109	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				110	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
				111	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
				112	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
				113	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	114	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
				115	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
				116	- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
				117	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				118	<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
				119	lu_result_sent == 1
				120	- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
				121	llist_count(&net->subscr_conns) == 1
				122	msc_subscr_conn_is_accepted() == false
				123	requests shall be thwarted
				124	DRLL Dispatching 04.08 message, pdisc=3
				125	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
				126	DRLL Dispatching 04.08 message, pdisc=5
				127	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
				128	DRLL Dispatching 04.08 message, pdisc=6
				129	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
				130	DRLL Dispatching 04.08 message, pdisc=9
				131	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
				132	- even though the TMSI is not acked, we can already find the subscr with it
				133	DREF VLR subscr MSISDN:42342 usage increases to: 2
				134	vsub != NULL == 1
				135	strcmp(vsub->imsi, imsi) == 0
				136	vsub->tmsi_new == 0x03020100
				137	vsub->tmsi == 0xffffffff
				138	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				139	- MS sends TMSI Realloc Complete
				140	rx from MS: pdisc=0x05 msg_type=0x5b
				141	DREF MSISDN:42342: MSC conn use + 1 == 2
				142	DRLL Dispatching 04.08 message, pdisc=5
				143	DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
				144	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
				145	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
				146	DREF VLR subscr MSISDN:42342 usage increases to: 2
				147	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	148	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
				149	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				150	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
				151	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
				152	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
				153	DVLR vlr_lu_fsm(901700000010650){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^]	154	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				155	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
				156	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				157	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				158	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
				159	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
				160	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	161	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				162	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
				163	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
				164	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
				165	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
				166	DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	167	DREF MSISDN:42342: MSC conn use - 1 == 1
				168	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
				169	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	170	DREF MSISDN:42342: MSC conn use - 1 == 0
				171	DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	172	DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	173	- LU was successful, and the conn has already been closed
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	174	llist_count(&net->subscr_conns) == 0
				175	---
				176	- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
				177	rx from MS: pdisc=0x05 msg_type=0x24
				178	new conn
				179	DREF unknown: MSC conn use + 1 == 1
				180	DRLL Dispatching 04.08 message, pdisc=5
				181	DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
				182	DREF unknown: MSC conn use + 1 == 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	183	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
				184	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				185	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	186	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
				187	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
				188	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth (no Ciph)
				189	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
				190	DREF VLR subscr MSISDN:42342 usage increases to: 2
				191	DREF VLR subscr MSISDN:42342 usage increases to: 3
				192	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
				193	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
				194	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
				195	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
				196	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
				197	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
				198	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
				199	- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
				200	- ...rand=c187a53a5e6b9d573cac7c74451fd46d
				201	- ...autn=1843a645b98d00005b2d666af46c45d9
				202	- ...expecting res=7db47cf7f81e4dc7
				203	DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	204	DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	205	DREF MSISDN:42342: MSC conn use - 1 == 1
				206	cm_service_result_sent == 0
				207	auth_request_sent == 1
				208	- needs auth, not yet accepted
				209	msc_subscr_conn_is_accepted() == false
				210	requests shall be thwarted
				211	DRLL Dispatching 04.08 message, pdisc=3
				212	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
				213	DRLL Dispatching 04.08 message, pdisc=5
				214	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
				215	DRLL Dispatching 04.08 message, pdisc=6
				216	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
				217	DRLL Dispatching 04.08 message, pdisc=9
				218	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
				219	- MS sends Authen Response, VLR accepts with a CM Service Accept
				220	rx from MS: pdisc=0x05 msg_type=0x54
				221	DREF MSISDN:42342: MSC conn use + 1 == 2
				222	DRLL Dispatching 04.08 message, pdisc=5
				223	DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
				224	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
				225	DVLR SUBSCR(MSISDN:42342) received res: 7d b4 7c f7 f8 1e 4d c7
				226	DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
				227	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
				228	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
				229	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				230	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
				231	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
				232	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
				233	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
				234	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
				235	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
				236	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
				237	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
				238	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
				239	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
				240	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
				241	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
				242	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
				243	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
				244	- sending CM Service Accept for MSISDN:42342
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	245	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				246	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
				247	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				248	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
				249	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				250	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
				251	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				252	DMM Subscr_Conn(901700000010650){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]	253	DREF MSISDN:42342: MSC conn use - 1 == 1
				254	cm_service_result_sent == 1
				255	- a USSD request is serviced
				256	expecting USSD:
				257	Your extension is 42342
				258	rx from MS: pdisc=0x0b msg_type=0x3b
				259	DREF MSISDN:42342: MSC conn use + 1 == 2
				260	DRLL Dispatching 04.08 message, pdisc=11
				261	DMM MSISDN:42342 pdisc=11 msg_type=0x3b: received_cm_service_request changes to false
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	262	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
				263	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	264	DMM USSD: Own number requested
				265	DMM MSISDN:42342: MSISDN = 42342
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	266	DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A
				267	- DTAP --RAN_GERAN_A--> MS: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	268	- DTAP matches expected message
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	269	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
				270	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
				271	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
				272	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	273	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				274	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
				275	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
				276	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
				277	DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
				278	DREF MSISDN:42342: MSC conn use - 1 == 1
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	279	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
				280	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	281	DREF MSISDN:42342: MSC conn use - 1 == 0
				282	DRLL subscr MSISDN:42342: Freeing subscriber connection
				283	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				284	- all requests serviced, conn has been released
				285	llist_count(&net->subscr_conns) == 0
				286	---
				287	- an SMS is sent, MS is paged
				288	DREF VLR subscr MSISDN:42342 usage increases to: 2
				289	llist_count(&vsub->cs.requests) == 0
				290	DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	291	DMM Subscriber MSISDN:42342 not paged yet, start paging.
				292	RAN_GERAN_A sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 0
				293	strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	294	DREF VLR subscr MSISDN:42342 usage increases to: 4
				295	llist_count(&vsub->cs.requests) == 1
				296	DREF VLR subscr MSISDN:42342 usage decreases to: 3
				297	paging_sent == 1
				298	paging_stopped == 0
				299	- the subscriber and its pending request should remain
				300	DREF VLR subscr MSISDN:42342 usage increases to: 4
				301	llist_count(&vsub->cs.requests) == 1
				302	DREF VLR subscr MSISDN:42342 usage decreases to: 3
				303	- MS replies with Paging Response, and VLR sends Auth Request with third key
				304	rx from MS: pdisc=0x06 msg_type=0x27
				305	new conn
				306	DREF unknown: MSC conn use + 1 == 1
				307	DRLL Dispatching 04.08 message, pdisc=6
				308	DRR PAGING RESPONSE: MI(IMSI)=901700000010650
				309	DREF unknown: MSC conn use + 1 == 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	310	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
				311	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				312	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	313	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
				314	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
				315	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=GERAN Auth (no Ciph)
				316	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
				317	DREF VLR subscr MSISDN:42342 usage increases to: 4
				318	DREF VLR subscr MSISDN:42342 usage increases to: 5
				319	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
				320	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
				321	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
				322	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
				323	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
				324	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
				325	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2
				326	- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
				327	- ...rand=efa9c29a9742148d5c9070348716e1bb
				328	- ...autn=f9375e6d41e1000096e7fe4ff1c27e39
				329	- ...expecting res=706f996719ba609c
				330	DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	331	DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	332	DREF MSISDN:42342: MSC conn use - 1 == 1
				333	auth_request_sent == 1
				334	- needs auth, not yet accepted
				335	msc_subscr_conn_is_accepted() == false
				336	requests shall be thwarted
				337	DRLL Dispatching 04.08 message, pdisc=3
				338	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
				339	DRLL Dispatching 04.08 message, pdisc=5
				340	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
				341	DRLL Dispatching 04.08 message, pdisc=6
				342	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
				343	DRLL Dispatching 04.08 message, pdisc=9
				344	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
				345	- MS sends Authen Response, VLR accepts and sends pending SMS
				346	rx from MS: pdisc=0x05 msg_type=0x54
				347	DREF MSISDN:42342: MSC conn use + 1 == 2
				348	DRLL Dispatching 04.08 message, pdisc=5
				349	DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 706f996719ba609c)
				350	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
				351	DVLR SUBSCR(MSISDN:42342) received res: 70 6f 99 67 19 ba 60 9c
				352	DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
				353	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
				354	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
				355	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				356	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
				357	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
				358	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
				359	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
				360	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
				361	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
				362	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_ciph()
				363	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2_post_vlr()
				364	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_pres()
				365	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace()
				366	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei()
				367	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
				368	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE
				369	DVLR Process_Access_Request_VLR(901700000010650){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^]	370	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				371	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
				372	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				373	DPAG Paging success for MSISDN:42342 (event=0)
				374	DPAG Calling paging cbfn.
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	375	DREF VLR subscr MSISDN:42342 usage increases to: 5
				376	DREF MSISDN:42342: MSC conn use + 1 == 3
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	377	DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_GERAN_A
				378	- DTAP --RAN_GERAN_A--> MS: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	379	- DTAP matches expected message
				380	DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	381	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				382	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_SMS
				383	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				384	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_SMS
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	385	DREF MSISDN:42342: MSC conn use - 1 == 2
				386	dtap_tx_confirmed == 1
				387	paging_stopped == 1
				388	- SMS was delivered, no requests pending for subscr
				389	DREF VLR subscr MSISDN:42342 usage increases to: 5
				390	llist_count(&vsub->cs.requests) == 0
				391	DREF VLR subscr MSISDN:42342 usage decreases to: 4
				392	- conn is still open to wait for SMS ack dance
				393	llist_count(&net->subscr_conns) == 1
				394	- MS replies with CP-ACK for received SMS
				395	rx from MS: pdisc=0x89 msg_type=0x04
				396	DREF MSISDN:42342: MSC conn use + 1 == 3
				397	DRLL Dispatching 04.08 message, pdisc=9
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	398	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
				399	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
				400	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
				401	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_SMS
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	402	DREF MSISDN:42342: MSC conn use - 1 == 2
				403	llist_count(&net->subscr_conns) == 1
				404	- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
				405	rx from MS: pdisc=0x89 msg_type=0x01
				406	DREF MSISDN:42342: MSC conn use + 1 == 3
				407	DRLL Dispatching 04.08 message, pdisc=9
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	408	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
				409	DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_GERAN_A
				410	- DTAP --RAN_GERAN_A--> MS: 0904
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	411	- DTAP matches expected message
				412	DREF VLR subscr MSISDN:42342 usage decreases to: 3
				413	DREF VLR subscr MSISDN:42342 usage decreases to: 2
				414	DREF MSISDN:42342: MSC conn use - 1 == 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	415	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
				416	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
				417	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
				418	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	419	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				420	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
				421	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
				422	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
				423	DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
				424	DREF MSISDN:42342: MSC conn use - 1 == 1
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	425	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
				426	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	427	DREF MSISDN:42342: MSC conn use - 1 == 0
				428	DRLL subscr MSISDN:42342: Freeing subscriber connection
				429	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				430	dtap_tx_confirmed == 1
				431	- SMS is done, conn is gone
				432	llist_count(&net->subscr_conns) == 0
				433	---
				434	- subscriber detaches
				435	rx from MS: pdisc=0x05 msg_type=0x01
				436	new conn
				437	DREF unknown: MSC conn use + 1 == 1
				438	DRLL Dispatching 04.08 message, pdisc=5
				439	DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
				440	DREF VLR subscr MSISDN:42342 usage increases to: 2
				441	DMM IMSI DETACH for MSISDN:42342
				442	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				443	DREF VLR subscr MSISDN:42342 usage decreases to: 0
				444	DREF freeing VLR subscr MSISDN:42342
				445	DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	446	DREF unknown: MSC conn use - 1 == 0
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	447	DRLL Freeing subscriber connection with NULL subscriber
				448	llist_count(&net->subscr_conns) == 0
				449	===== test_umts_authen_geran: SUCCESS
				450
				451	full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	452	talloc_total_blocks(tall_bsc_ctx) == 9
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	453
				454	===== test_umts_authen_utran
				455	- Location Update request causes a GSUP Send Auth Info request to HLR
				456	rx from MS: pdisc=0x05 msg_type=0x08
				457	new conn
				458	DREF unknown: MSC conn use + 1 == 1
				459	DRLL Dispatching 04.08 message, pdisc=5
				460	DREF unknown: MSC conn use + 1 == 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	461	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
				462	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				463	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	464	DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
				465	DMM LU/new-LAC: 0/0
				466	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
				467	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	468	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	469	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
				470	DREF VLR subscr unknown usage increases to: 1
				471	DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
				472	DVLR New subscr, IMSI: 901700000010650
				473	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr	54a706c	2017-07-18 15:39:27 +0200	[diff] [blame]	474	DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	475	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
				476	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
				477	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
				478	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
				479	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
				480	DVLR GSUP tx: 08010809710000000156f0
				481	GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
				482	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	483	DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	484	DREF IMSI:901700000010650: MSC conn use - 1 == 1
				485	lu_result_sent == 0
				486	- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
				487	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
				488	DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
				489	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
				490	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
				491	DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
				492	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
				493	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
				494	- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
				495	- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
				496	- ...autn=8704f5ba55f30000d2ee44b22c8ea919
				497	- ...expecting res=e229c19e791f2e41
				498	DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
				499	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
				500	auth_request_sent == 1
				501	lu_result_sent == 0
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	502	- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	503	rx from MS: pdisc=0x05 msg_type=0x54
				504	DREF IMSI:901700000010650: MSC conn use + 1 == 2
				505	DRLL Dispatching 04.08 message, pdisc=5
				506	DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
				507	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
				508	DVLR SUBSCR(IMSI:901700000010650) received res: e2 29 c1 9e 79 1f 2e 41
				509	DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
				510	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
				511	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
				512	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				513	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
				514	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
				515	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
				516	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
				517	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	518	- sending SecurityModeControl for IMSI:901700000010650
				519	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
				520	DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
				521	DREF IMSI:901700000010650: MSC conn use - 1 == 1
				522	cipher_mode_cmd_sent == 1
				523	lu_result_sent == 0
				524	- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
				525	DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
				526	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
				527	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
				528	DIUCS IMSI:901700000010650: tx CommonID 901700000010650
				529	- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
				530	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
				531	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	532	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
				533	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
				534	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
				535	DVLR GSUP tx: 04010809710000000156f0
				536	GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
				537	DVLR upd_hlr_vlr_fsm(901700000010650){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^]	538	gsup_tx_confirmed == 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	539	lu_result_sent == 0
				540	- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
				541	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
				542	DVLR GSUP rx 17: 10010809710000000156f00804032443f2
				543	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
				544	DVLR IMSI:901700000010650 has MSISDN:42342
				545	DVLR GSUP tx: 12010809710000000156f0
				546	GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
				547	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				548	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
				549	lu_result_sent == 0
				550	- HLR also sends GSUP _UPDATE_LOCATION_RESULT
				551	<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
				552	DVLR GSUP rx 11: 06010809710000000156f0
				553	DREF VLR subscr MSISDN:42342 usage increases to: 2
				554	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
				555	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
				556	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
				557	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				558	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
				559	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
				560	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
				561	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
				562	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
				563	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
				564	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
				565	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
				566	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
				567	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
				568	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
				569	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
				570	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
				571	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				572	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
				573	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
				574	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
				575	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	576	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
				577	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
				578	- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
				579	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				580	<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
				581	lu_result_sent == 1
				582	- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
				583	llist_count(&net->subscr_conns) == 1
				584	msc_subscr_conn_is_accepted() == false
				585	requests shall be thwarted
				586	DRLL Dispatching 04.08 message, pdisc=3
				587	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
				588	DRLL Dispatching 04.08 message, pdisc=5
				589	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
				590	DRLL Dispatching 04.08 message, pdisc=6
				591	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
				592	DRLL Dispatching 04.08 message, pdisc=9
				593	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
				594	- even though the TMSI is not acked, we can already find the subscr with it
				595	DREF VLR subscr MSISDN:42342 usage increases to: 2
				596	vsub != NULL == 1
				597	strcmp(vsub->imsi, imsi) == 0
				598	vsub->tmsi_new == 0x03020100
				599	vsub->tmsi == 0xffffffff
				600	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				601	- MS sends TMSI Realloc Complete
				602	rx from MS: pdisc=0x05 msg_type=0x5b
				603	DREF MSISDN:42342: MSC conn use + 1 == 2
				604	DRLL Dispatching 04.08 message, pdisc=5
				605	DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
				606	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
				607	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
				608	DREF VLR subscr MSISDN:42342 usage increases to: 2
				609	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	610	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
				611	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				612	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
				613	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
				614	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
				615	DVLR vlr_lu_fsm(901700000010650){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^]	616	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				617	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
				618	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				619	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				620	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
				621	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
				622	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	623	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				624	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
				625	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
				626	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
				627	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
				628	DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	629	- Iu Release --RAN_UTRAN_IU--> MS
				630	DREF MSISDN:42342: MSC conn use - 1 == 1
				631	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
				632	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	633	DREF MSISDN:42342: MSC conn use - 1 == 0
				634	DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	635	DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	636	- LU was successful, and the conn has already been closed
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	637	llist_count(&net->subscr_conns) == 0
				638	---
				639	- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
				640	rx from MS: pdisc=0x05 msg_type=0x24
				641	new conn
				642	DREF unknown: MSC conn use + 1 == 1
				643	DRLL Dispatching 04.08 message, pdisc=5
				644	DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
				645	DREF unknown: MSC conn use + 1 == 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	646	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
				647	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				648	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	649	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
				650	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	651	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	652	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
				653	DREF VLR subscr MSISDN:42342 usage increases to: 2
				654	DREF VLR subscr MSISDN:42342 usage increases to: 3
				655	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
				656	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
				657	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
				658	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
				659	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
				660	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
				661	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
				662	- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
				663	- ...rand=c187a53a5e6b9d573cac7c74451fd46d
				664	- ...autn=1843a645b98d00005b2d666af46c45d9
				665	- ...expecting res=7db47cf7f81e4dc7
				666	DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	667	DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	668	DREF MSISDN:42342: MSC conn use - 1 == 1
				669	cm_service_result_sent == 0
				670	auth_request_sent == 1
				671	- needs auth, not yet accepted
				672	msc_subscr_conn_is_accepted() == false
				673	requests shall be thwarted
				674	DRLL Dispatching 04.08 message, pdisc=3
				675	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
				676	DRLL Dispatching 04.08 message, pdisc=5
				677	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
				678	DRLL Dispatching 04.08 message, pdisc=6
				679	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
				680	DRLL Dispatching 04.08 message, pdisc=9
				681	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	682	- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	683	rx from MS: pdisc=0x05 msg_type=0x54
				684	DREF MSISDN:42342: MSC conn use + 1 == 2
				685	DRLL Dispatching 04.08 message, pdisc=5
				686	DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
				687	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
				688	DVLR SUBSCR(MSISDN:42342) received res: 7d b4 7c f7 f8 1e 4d c7
				689	DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
				690	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
				691	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
				692	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				693	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
				694	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
				695	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
				696	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
				697	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
				698	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	699	- sending SecurityModeControl for MSISDN:42342
				700	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
				701	DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	702	DREF MSISDN:42342: MSC conn use - 1 == 1
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	703	cipher_mode_cmd_sent == 1
				704	cm_service_result_sent == 0
				705	- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
				706	DMM <- SECURITY MODE COMPLETE MSISDN:42342
				707	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
				708	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
				709	DIUCS MSISDN:42342: tx CommonID 901700000010650
				710	- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
				711	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
				712	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
				713	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
				714	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
				715	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
				716	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
				717	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
				718	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				719	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
				720	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				721	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
				722	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				723	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
				724	cm_service_result_sent == 0
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	725	- a USSD request is serviced
				726	expecting USSD:
				727	Your extension is 42342
				728	rx from MS: pdisc=0x0b msg_type=0x3b
				729	DREF MSISDN:42342: MSC conn use + 1 == 2
				730	DRLL Dispatching 04.08 message, pdisc=11
				731	DMM MSISDN:42342 pdisc=11 msg_type=0x3b: received_cm_service_request changes to false
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	732	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
				733	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	734	DMM USSD: Own number requested
				735	DMM MSISDN:42342: MSISDN = 42342
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	736	DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_UTRAN_IU
				737	- DTAP --RAN_UTRAN_IU--> MS: 8b2a1c27a225020100302002013b301b04010f0416d9775d0e2ae3e965f73cfd7683d273104d36a3c91a0d
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	738	- DTAP matches expected message
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	739	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
				740	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
				741	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
				742	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	743	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				744	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
				745	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
				746	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
				747	DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	748	- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	749	DREF MSISDN:42342: MSC conn use - 1 == 1
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	750	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
				751	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	752	DREF MSISDN:42342: MSC conn use - 1 == 0
				753	DRLL subscr MSISDN:42342: Freeing subscriber connection
				754	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				755	- all requests serviced, conn has been released
				756	llist_count(&net->subscr_conns) == 0
				757	---
				758	- an SMS is sent, MS is paged
				759	DREF VLR subscr MSISDN:42342 usage increases to: 2
				760	llist_count(&vsub->cs.requests) == 0
				761	DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	762	DMM Subscriber MSISDN:42342 not paged yet, start paging.
				763	RAN_UTRAN_IU sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 0
				764	strcmp(paging_expecting_imsi, imsi) == 0
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	765	DREF VLR subscr MSISDN:42342 usage increases to: 4
				766	llist_count(&vsub->cs.requests) == 1
				767	DREF VLR subscr MSISDN:42342 usage decreases to: 3
				768	paging_sent == 1
				769	paging_stopped == 0
				770	- the subscriber and its pending request should remain
				771	DREF VLR subscr MSISDN:42342 usage increases to: 4
				772	llist_count(&vsub->cs.requests) == 1
				773	DREF VLR subscr MSISDN:42342 usage decreases to: 3
				774	- MS replies with Paging Response, and VLR sends Auth Request with third key
				775	rx from MS: pdisc=0x06 msg_type=0x27
				776	new conn
				777	DREF unknown: MSC conn use + 1 == 1
				778	DRLL Dispatching 04.08 message, pdisc=6
				779	DRR PAGING RESPONSE: MI(IMSI)=901700000010650
				780	DREF unknown: MSC conn use + 1 == 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	781	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
				782	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				783	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	784	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
				785	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	786	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	787	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
				788	DREF VLR subscr MSISDN:42342 usage increases to: 4
				789	DREF VLR subscr MSISDN:42342 usage increases to: 5
				790	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
				791	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
				792	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
				793	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
				794	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
				795	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
				796	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=2
				797	- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=2 auth_types=0x3 and...
				798	- ...rand=efa9c29a9742148d5c9070348716e1bb
				799	- ...autn=f9375e6d41e1000096e7fe4ff1c27e39
				800	- ...expecting res=706f996719ba609c
				801	DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	802	DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	803	DREF MSISDN:42342: MSC conn use - 1 == 1
				804	auth_request_sent == 1
				805	- needs auth, not yet accepted
				806	msc_subscr_conn_is_accepted() == false
				807	requests shall be thwarted
				808	DRLL Dispatching 04.08 message, pdisc=3
				809	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
				810	DRLL Dispatching 04.08 message, pdisc=5
				811	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
				812	DRLL Dispatching 04.08 message, pdisc=6
				813	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
				814	DRLL Dispatching 04.08 message, pdisc=9
				815	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	816	- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	817	rx from MS: pdisc=0x05 msg_type=0x54
				818	DREF MSISDN:42342: MSC conn use + 1 == 2
				819	DRLL Dispatching 04.08 message, pdisc=5
				820	DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 706f996719ba609c)
				821	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
				822	DVLR SUBSCR(MSISDN:42342) received res: 70 6f 99 67 19 ba 60 9c
				823	DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
				824	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
				825	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
				826	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				827	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
				828	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
				829	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
				830	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
				831	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
				832	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	833	- sending SecurityModeControl for MSISDN:42342
				834	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
				835	DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
				836	DREF MSISDN:42342: MSC conn use - 1 == 1
				837	cipher_mode_cmd_sent == 1
				838	paging_stopped == 0
				839	- MS sends SecurityModeControl acceptance, VLR accepts and sends SMS
				840	DMM <- SECURITY MODE COMPLETE MSISDN:42342
				841	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
				842	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
				843	DIUCS MSISDN:42342: tx CommonID 901700000010650
				844	- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
				845	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
				846	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
				847	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
				848	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
				849	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
				850	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	851	DVLR Process_Access_Request_VLR(901700000010650){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^]	852	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				853	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
				854	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				855	DPAG Paging success for MSISDN:42342 (event=0)
				856	DPAG Calling paging cbfn.
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	857	DREF VLR subscr MSISDN:42342 usage increases to: 5
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	858	DREF MSISDN:42342: MSC conn use + 1 == 2
				859	DMSC msc_tx 91 bytes to MSISDN:42342 via RAN_UTRAN_IU
				860	- DTAP --RAN_UTRAN_IU--> MS: 09015801000791447758100650004c0005802443f2000007101000000000445079da1e1ee7416937485e9ea7c965373d1d6683c270383b3d0ed3d36ff71c949e83c22072799e9687c5ec32a81d96afcbf4b4fb0c7ac3e9e9b7db05
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	861	- DTAP matches expected message
				862	DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	863	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				864	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_SMS
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	865	paging_stopped == 1
				866	- SMS was delivered, no requests pending for subscr
				867	DREF VLR subscr MSISDN:42342 usage increases to: 5
				868	llist_count(&vsub->cs.requests) == 0
				869	DREF VLR subscr MSISDN:42342 usage decreases to: 4
				870	- conn is still open to wait for SMS ack dance
				871	llist_count(&net->subscr_conns) == 1
				872	- MS replies with CP-ACK for received SMS
				873	rx from MS: pdisc=0x89 msg_type=0x04
				874	DREF MSISDN:42342: MSC conn use + 1 == 3
				875	DRLL Dispatching 04.08 message, pdisc=9
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	876	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
				877	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
				878	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
				879	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_SMS
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	880	DREF MSISDN:42342: MSC conn use - 1 == 2
				881	llist_count(&net->subscr_conns) == 1
				882	- MS also sends RP-ACK, MSC in turn sends CP-ACK for that
				883	rx from MS: pdisc=0x89 msg_type=0x01
				884	DREF MSISDN:42342: MSC conn use + 1 == 3
				885	DRLL Dispatching 04.08 message, pdisc=9
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	886	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
				887	DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
				888	- DTAP --RAN_UTRAN_IU--> MS: 0904
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	889	- DTAP matches expected message
				890	DREF VLR subscr MSISDN:42342 usage decreases to: 3
				891	DREF VLR subscr MSISDN:42342 usage decreases to: 2
				892	DREF MSISDN:42342: MSC conn use - 1 == 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	893	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
				894	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
				895	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
				896	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	897	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				898	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
				899	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
				900	DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
				901	DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	902	- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	903	DREF MSISDN:42342: MSC conn use - 1 == 1
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	904	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
				905	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	906	DREF MSISDN:42342: MSC conn use - 1 == 0
				907	DRLL subscr MSISDN:42342: Freeing subscriber connection
				908	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				909	dtap_tx_confirmed == 1
				910	- SMS is done, conn is gone
				911	llist_count(&net->subscr_conns) == 0
				912	---
				913	- subscriber detaches
				914	rx from MS: pdisc=0x05 msg_type=0x01
				915	new conn
				916	DREF unknown: MSC conn use + 1 == 1
				917	DRLL Dispatching 04.08 message, pdisc=5
				918	DMM IMSI DETACH INDICATION: MI(IMSI)=901700000010650
				919	DREF VLR subscr MSISDN:42342 usage increases to: 2
				920	DMM IMSI DETACH for MSISDN:42342
				921	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				922	DREF VLR subscr MSISDN:42342 usage decreases to: 0
				923	DREF freeing VLR subscr MSISDN:42342
				924	DMM msc_subscr_conn_close(vsub=unknown, cause=0): no conn fsm, releasing directly without release event.
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	925	- Iu Release --RAN_UTRAN_IU--> MS
				926	DREF unknown: MSC conn use - 1 == 0
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	927	DRLL Freeing subscriber connection with NULL subscriber
				928	llist_count(&net->subscr_conns) == 0
				929	===== test_umts_authen_utran: SUCCESS
				930
				931	full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	932	talloc_total_blocks(tall_bsc_ctx) == 9
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	933
				934	===== test_umts_authen_resync_geran
				935	- Location Update request causes a GSUP Send Auth Info request to HLR
				936	rx from MS: pdisc=0x05 msg_type=0x08
				937	new conn
				938	DREF unknown: MSC conn use + 1 == 1
				939	DRLL Dispatching 04.08 message, pdisc=5
				940	DREF unknown: MSC conn use + 1 == 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	941	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
				942	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				943	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	944	DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
				945	DMM LU/new-LAC: 0/0
				946	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
				947	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
				948	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=GERAN Auth (no Ciph)
				949	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
				950	DREF VLR subscr unknown usage increases to: 1
				951	DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
				952	DVLR New subscr, IMSI: 901700000010650
				953	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr	54a706c	2017-07-18 15:39:27 +0200	[diff] [blame]	954	DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	955	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
				956	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
				957	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
				958	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
				959	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
				960	DVLR GSUP tx: 08010809710000000156f0
				961	GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
				962	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	963	DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	964	DREF IMSI:901700000010650: MSC conn use - 1 == 1
				965	lu_result_sent == 0
				966	- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
				967	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
				968	DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
				969	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
				970	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
				971	DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples
				972	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
				973	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
				974	- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
				975	- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
				976	- ...autn=8704f5ba55f30000d2ee44b22c8ea919
				977	- ...expecting res=e229c19e791f2e41
				978	DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
				979	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
				980	auth_request_sent == 1
				981	lu_result_sent == 0
				982	- MS sends Authen Failure with Resync cause, VLR sends GSUP to HLR to resync
				983	rx from MS: pdisc=0x05 msg_type=0x1c
				984	DREF IMSI:901700000010650: MSC conn use + 1 == 2
				985	DRLL Dispatching 04.08 message, pdisc=5
				986	DMM IMSI:901700000010650: MM R99 AUTHENTICATION SYNCH (AUTS = 979498b1f72d3e28c59fa2e72f9c)
				987	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_FAIL
				988	DVLR GSUP tx: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
				989	GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
				990	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	991	DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	992	DREF IMSI:901700000010650: MSC conn use - 1 == 1
				993	gsup_tx_confirmed == 1
				994	auth_request_sent == 0
				995	lu_result_sent == 0
				996	- HLR replies with new tuples
				997	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
				998	DVLR GSUP rx 211: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
				999	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
				1000	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: Received Event VLR_AUTH_E_HLR_SAI_ACK
				1001	DVLR SUBSCR(IMSI:901700000010650) Received 2 auth tuples
				1002	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: state_chg to VLR_SUB_AS_WAIT_RESP_RESYNC
				1003	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: got auth tuple: use_count=1 key_seq=0
				1004	- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
				1005	- ...rand=0f1feb1623e1bf626334e37ec448ac18
				1006	- ...autn=02a83f62e9470000660d51afc75f169d
				1007	- ...expecting res=1df5f0b4f22b696e
				1008	DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
				1009	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
				1010	auth_request_sent == 1
				1011	lu_result_sent == 0
				1012	- MS sends Authen Response, VLR accepts and sends GSUP LU Req to HLR
				1013	rx from MS: pdisc=0x05 msg_type=0x54
				1014	DREF IMSI:901700000010650: MSC conn use + 1 == 2
				1015	DRLL Dispatching 04.08 message, pdisc=5
				1016	DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = 1df5f0b4f22b696e)
				1017	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Received Event VLR_AUTH_E_MS_AUTH_RESP
				1018	DVLR SUBSCR(IMSI:901700000010650) received res: 1d f5 f0 b4 f2 2b 69 6e
				1019	DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
				1020	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Authentication terminating with result VLR_AUTH_RES_PASSED
				1021	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: state_chg to VLR_SUB_AS_AUTHENTICATED
				1022	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				1023	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
				1024	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
				1025	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
				1026	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
				1027	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
				1028	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph()
				1029	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4()
				1030	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
				1031	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
				1032	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
				1033	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
				1034	DVLR GSUP tx: 04010809710000000156f0
				1035	GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
				1036	DVLR upd_hlr_vlr_fsm(901700000010650){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^]	1037	DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1038	DREF IMSI:901700000010650: MSC conn use - 1 == 1
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1039	gsup_tx_confirmed == 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1040	lu_result_sent == 0
				1041	- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
				1042	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
				1043	DVLR GSUP rx 17: 10010809710000000156f00804032443f2
				1044	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
				1045	DVLR IMSI:901700000010650 has MSISDN:42342
				1046	DVLR GSUP tx: 12010809710000000156f0
				1047	GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
				1048	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				1049	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
				1050	lu_result_sent == 0
				1051	- HLR also sends GSUP _UPDATE_LOCATION_RESULT
				1052	<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
				1053	DVLR GSUP rx 11: 06010809710000000156f0
				1054	DREF VLR subscr MSISDN:42342 usage increases to: 2
				1055	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
				1056	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
				1057	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
				1058	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				1059	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
				1060	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
				1061	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
				1062	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
				1063	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
				1064	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
				1065	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
				1066	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
				1067	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
				1068	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
				1069	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
				1070	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
				1071	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
				1072	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				1073	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
				1074	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
				1075	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
				1076	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1077	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
				1078	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
				1079	- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
				1080	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				1081	<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
				1082	lu_result_sent == 1
				1083	- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
				1084	llist_count(&net->subscr_conns) == 1
				1085	msc_subscr_conn_is_accepted() == false
				1086	requests shall be thwarted
				1087	DRLL Dispatching 04.08 message, pdisc=3
				1088	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
				1089	DRLL Dispatching 04.08 message, pdisc=5
				1090	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
				1091	DRLL Dispatching 04.08 message, pdisc=6
				1092	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
				1093	DRLL Dispatching 04.08 message, pdisc=9
				1094	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
				1095	- even though the TMSI is not acked, we can already find the subscr with it
				1096	DREF VLR subscr MSISDN:42342 usage increases to: 2
				1097	vsub != NULL == 1
				1098	strcmp(vsub->imsi, imsi) == 0
				1099	vsub->tmsi_new == 0x03020100
				1100	vsub->tmsi == 0xffffffff
				1101	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				1102	- MS sends TMSI Realloc Complete
				1103	rx from MS: pdisc=0x05 msg_type=0x5b
				1104	DREF MSISDN:42342: MSC conn use + 1 == 2
				1105	DRLL Dispatching 04.08 message, pdisc=5
				1106	DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
				1107	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
				1108	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
				1109	DREF VLR subscr MSISDN:42342 usage increases to: 2
				1110	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1111	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
				1112	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				1113	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
				1114	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
				1115	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
				1116	DVLR vlr_lu_fsm(901700000010650){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^]	1117	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				1118	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
				1119	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				1120	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				1121	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
				1122	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
				1123	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1124	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				1125	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
				1126	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
				1127	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
				1128	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
				1129	DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1130	DREF MSISDN:42342: MSC conn use - 1 == 1
				1131	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
				1132	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1133	DREF MSISDN:42342: MSC conn use - 1 == 0
				1134	DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1135	DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1136	- LU was successful, and the conn has already been closed
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1137	llist_count(&net->subscr_conns) == 0
				1138	DREF freeing VLR subscr MSISDN:42342
				1139	===== test_umts_authen_resync_geran: SUCCESS
				1140
				1141	full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1142	talloc_total_blocks(tall_bsc_ctx) == 9
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1143
				1144	===== test_umts_authen_resync_utran
				1145	- Location Update request causes a GSUP Send Auth Info request to HLR
				1146	rx from MS: pdisc=0x05 msg_type=0x08
				1147	new conn
				1148	DREF unknown: MSC conn use + 1 == 1
				1149	DRLL Dispatching 04.08 message, pdisc=5
				1150	DREF unknown: MSC conn use + 1 == 2
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1151	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
				1152	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
				1153	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1154	DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
				1155	DMM LU/new-LAC: 0/0
				1156	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
				1157	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1158	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1159	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
				1160	DREF VLR subscr unknown usage increases to: 1
				1161	DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
				1162	DVLR New subscr, IMSI: 901700000010650
				1163	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyr	54a706c	2017-07-18 15:39:27 +0200	[diff] [blame]	1164	DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1165	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
				1166	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
				1167	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
				1168	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
				1169	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
				1170	DVLR GSUP tx: 08010809710000000156f0
				1171	GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
				1172	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1173	DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1174	DREF IMSI:901700000010650: MSC conn use - 1 == 1
				1175	lu_result_sent == 0
				1176	- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
				1177	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
				1178	DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e41
				1179	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
				1180	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
				1181	DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples
				1182	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
				1183	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
				1184	- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
				1185	- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
				1186	- ...autn=8704f5ba55f30000d2ee44b22c8ea919
				1187	- ...expecting res=e229c19e791f2e41
				1188	DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
				1189	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
				1190	auth_request_sent == 1
				1191	lu_result_sent == 0
				1192	- MS sends Authen Failure with Resync cause, VLR sends GSUP to HLR to resync
				1193	rx from MS: pdisc=0x05 msg_type=0x1c
				1194	DREF IMSI:901700000010650: MSC conn use + 1 == 2
				1195	DRLL Dispatching 04.08 message, pdisc=5
				1196	DMM IMSI:901700000010650: MM R99 AUTHENTICATION SYNCH (AUTS = 979498b1f72d3e28c59fa2e72f9c)
				1197	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_FAIL
				1198	DVLR GSUP tx: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
				1199	GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0260e979498b1f72d3e28c59fa2e72f9c201039fa2f4e3d523d8619a73b4f65c3e14d
				1200	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1201	DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1202	DREF IMSI:901700000010650: MSC conn use - 1 == 1
				1203	gsup_tx_confirmed == 1
				1204	auth_request_sent == 0
				1205	lu_result_sent == 0
				1206	- HLR replies with new tuples
				1207	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
				1208	DVLR GSUP rx 211: 0a010809710000000156f0036220100f1feb1623e1bf626334e37ec448ac182104efde99da220814778c855c52373023108a90c769b7272f3bb7a1c1fbb1ea9349241043ffc1cf8c89a7fd6ab94bd8d6162cbf251002a83f62e9470000660d51afc75f169d27081df5f0b4f22b696e03622010ac21d34937b4e1142a2c757af294931921047818bfdc2208d175571f41f314a42310ff8edbceb6dd24799c77c3b9a6790c102410157c39022ca9d885a7f0766a7dfee44825108a43b91898e500002cf354c6f5d1f8c32708f748a7078f5018db
				1209	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
				1210	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: Received Event VLR_AUTH_E_HLR_SAI_ACK
				1211	DVLR SUBSCR(IMSI:901700000010650) Received 2 auth tuples
				1212	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_SAI_RESYNC}: state_chg to VLR_SUB_AS_WAIT_RESP_RESYNC
				1213	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: got auth tuple: use_count=1 key_seq=0
				1214	- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
				1215	- ...rand=0f1feb1623e1bf626334e37ec448ac18
				1216	- ...autn=02a83f62e9470000660d51afc75f169d
				1217	- ...expecting res=1df5f0b4f22b696e
				1218	DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
				1219	<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
				1220	auth_request_sent == 1
				1221	lu_result_sent == 0
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1222	- MS sends Authen Response, VLR accepts and sends SecurityModeControl
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1223	rx from MS: pdisc=0x05 msg_type=0x54
				1224	DREF IMSI:901700000010650: MSC conn use + 1 == 2
				1225	DRLL Dispatching 04.08 message, pdisc=5
				1226	DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = 1df5f0b4f22b696e)
				1227	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Received Event VLR_AUTH_E_MS_AUTH_RESP
				1228	DVLR SUBSCR(IMSI:901700000010650) received res: 1d f5 f0 b4 f2 2b 69 6e
				1229	DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
				1230	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: Authentication terminating with result VLR_AUTH_RES_PASSED
				1231	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP_RESYNC}: state_chg to VLR_SUB_AS_AUTHENTICATED
				1232	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				1233	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
				1234	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
				1235	DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
				1236	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
				1237	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1238	- sending SecurityModeControl for IMSI:901700000010650
				1239	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
				1240	DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
				1241	DREF IMSI:901700000010650: MSC conn use - 1 == 1
				1242	cipher_mode_cmd_sent == 1
				1243	lu_result_sent == 0
				1244	- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
				1245	DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
				1246	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
				1247	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
				1248	DIUCS IMSI:901700000010650: tx CommonID 901700000010650
				1249	- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
				1250	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
				1251	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1252	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
				1253	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
				1254	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
				1255	DVLR GSUP tx: 04010809710000000156f0
				1256	GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
				1257	DVLR upd_hlr_vlr_fsm(901700000010650){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^]	1258	gsup_tx_confirmed == 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1259	lu_result_sent == 0
				1260	- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
				1261	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
				1262	DVLR GSUP rx 17: 10010809710000000156f00804032443f2
				1263	DREF VLR subscr IMSI:901700000010650 usage increases to: 2
				1264	DVLR IMSI:901700000010650 has MSISDN:42342
				1265	DVLR GSUP tx: 12010809710000000156f0
				1266	GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
				1267	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				1268	<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
				1269	lu_result_sent == 0
				1270	- HLR also sends GSUP _UPDATE_LOCATION_RESULT
				1271	<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
				1272	DVLR GSUP rx 11: 06010809710000000156f0
				1273	DREF VLR subscr MSISDN:42342 usage increases to: 2
				1274	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
				1275	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
				1276	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
				1277	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				1278	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
				1279	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
				1280	DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
				1281	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
				1282	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
				1283	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
				1284	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
				1285	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
				1286	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
				1287	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
				1288	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
				1289	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
				1290	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
				1291	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
				1292	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
				1293	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
				1294	DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
				1295	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1296	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
				1297	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
				1298	- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
				1299	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				1300	<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
				1301	lu_result_sent == 1
				1302	- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
				1303	llist_count(&net->subscr_conns) == 1
				1304	msc_subscr_conn_is_accepted() == false
				1305	requests shall be thwarted
				1306	DRLL Dispatching 04.08 message, pdisc=3
				1307	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x03 msg_type=0x05
				1308	DRLL Dispatching 04.08 message, pdisc=5
				1309	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x05 msg_type=0x33
				1310	DRLL Dispatching 04.08 message, pdisc=6
				1311	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x06 msg_type=0x19
				1312	DRLL Dispatching 04.08 message, pdisc=9
				1313	DRLL subscr MSISDN:42342: Message not permitted for initial conn: pdisc=0x09 msg_type=0x01
				1314	- even though the TMSI is not acked, we can already find the subscr with it
				1315	DREF VLR subscr MSISDN:42342 usage increases to: 2
				1316	vsub != NULL == 1
				1317	strcmp(vsub->imsi, imsi) == 0
				1318	vsub->tmsi_new == 0x03020100
				1319	vsub->tmsi == 0xffffffff
				1320	DREF VLR subscr MSISDN:42342 usage decreases to: 1
				1321	- MS sends TMSI Realloc Complete
				1322	rx from MS: pdisc=0x05 msg_type=0x5b
				1323	DREF MSISDN:42342: MSC conn use + 1 == 2
				1324	DRLL Dispatching 04.08 message, pdisc=5
				1325	DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
				1326	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
				1327	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
				1328	DREF VLR subscr MSISDN:42342 usage increases to: 2
				1329	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1330	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
				1331	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				1332	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
				1333	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
				1334	DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
				1335	DVLR vlr_lu_fsm(901700000010650){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^]	1336	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
				1337	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
				1338	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
				1339	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
				1340	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
				1341	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
				1342	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1343	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
				1344	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
				1345	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
				1346	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
				1347	DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
				1348	DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1349	- Iu Release --RAN_UTRAN_IU--> MS
				1350	DREF MSISDN:42342: MSC conn use - 1 == 1
				1351	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
				1352	DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1353	DREF MSISDN:42342: MSC conn use - 1 == 0
				1354	DRLL subscr MSISDN:42342: Freeing subscriber connection
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1355	DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1356	- LU was successful, and the conn has already been closed
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1357	llist_count(&net->subscr_conns) == 0
				1358	DREF freeing VLR subscr MSISDN:42342
				1359	===== test_umts_authen_resync_utran: SUCCESS
				1360
				1361	full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr	84da6b1	2016-05-20 21:59:55 +0200	[diff] [blame^]	1362	talloc_total_blocks(tall_bsc_ctx) == 9
Neels Hofmeyr	6a29d32	2017-01-25 15:04:16 +0100	[diff] [blame]	1363
				1364	full talloc report on 'msgb' (total 0 bytes in 1 blocks)
				1365	talloc_total_blocks(tall_bsc_ctx) == 9
				1366