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

blob: 1b8002b16c51b9a798008e37f76eafcc7c53b974 [file] [log] [blame]

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