Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / 16c42b5fbacb93867f41f529893b6af8a1a54c5b / . / tests / msc_vlr / msc_vlr_test_call.err
blob: 281f418804ecd98c2f65cbf0f413df631d58b2ed [file] [log] [blame]
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1full talloc report on 'msgb' (total 0 bytes in 1 blocks)
2talloc_total_blocks(tall_bsc_ctx) == 12
3
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]4===== test_call_mo
Neels Hofmeyra99b4272017-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
9DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
10DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
11DREF unknown: MSC conn use + fsm == 2 (0x5)
12DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
13DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
14DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame^]15DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]16DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
17DMM LU/new-LAC: 23/23
18DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
19DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
20DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
21DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
22DREF VLR subscr unknown usage increases to: 1
23DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
24DVLR New subscr, IMSI: 901700000010650
25DREF VLR subscr IMSI:901700000010650 usage increases to: 2
26DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
27DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
28DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
29DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
30DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
31DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
32DVLR GSUP tx: 08010809710000000156f0
33GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
34DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]35DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]36DREF 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
40DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
41DREF VLR subscr IMSI:901700000010650 usage increases to: 2
42DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
43DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
44DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100[diff] [blame]45DVLR 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 Hofmeyra99b4272017-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
50DREF 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
56DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
57DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100[diff] [blame]58DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]59DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100[diff] [blame]60DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]61DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
62DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
63DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
64DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
65DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
66DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
67DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
68DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
69DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +0100[diff] [blame]70DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100[diff] [blame]71DMM -> SECURITY MODE CONTROL IMSI:901700000010650
72- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
73- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]74DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]75DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]76DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100[diff] [blame]77 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-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
80DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
81DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
82DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
83DIUCS IMSI:901700000010650: tx CommonID 901700000010650
84- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
85DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
86DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
87DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
88DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
89DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
90DVLR GSUP tx: 04010809710000000156f0
91GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
92DVLR 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
97DVLR GSUP rx 17: 10010809710000000156f00804032443f2
98DREF VLR subscr IMSI:901700000010650 usage increases to: 2
99DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]100DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]101DVLR GSUP tx: 12010809710000000156f0
102GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
103DREF 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
108DVLR GSUP rx 11: 06010809710000000156f0
109DREF VLR subscr MSISDN:42342 usage increases to: 2
110DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
111DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
112DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
113DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
114DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
115DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
116DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
117DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
118DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
119DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
120DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
121DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
122DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
123DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
124DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
125DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
126DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
127DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
128DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
129DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
130DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
131DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
132DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
133DVLR 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
135DREF 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
140msc_subscr_conn_is_accepted() == false
141- MS sends TMSI Realloc Complete
142 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
143DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
144DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
145DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
146DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
147DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
148DREF VLR subscr MSISDN:42342 usage increases to: 2
149DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
150DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
151DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
152DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
153DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
154DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
155DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
156DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]157DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]158DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
159DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]160DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
161DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
162DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
163DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
164DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
165DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
166DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
167DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
168- Iu Release --RAN_UTRAN_IU--> MS
169DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
170DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
171DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
172DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
173DRLL subscr MSISDN:42342: Freeing subscriber connection
174DREF 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
178DREF VLR subscr MSISDN:42342 usage increases to: 2
179 vsub != NULL == 1
180 strcmp(vsub->imsi, IMSI) == 0
181 vsub->lac == 23
182DREF 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
187DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
188DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
189DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
190DREF unknown: MSC conn use + fsm == 2 (0x5)
191DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
192DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
193DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame^]194DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]195DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
196DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
197DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
198DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
199DREF VLR subscr MSISDN:42342 usage increases to: 2
200DREF VLR subscr MSISDN:42342 usage increases to: 3
201DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
202DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
203DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
204DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
205DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
206DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100[diff] [blame]207DVLR 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 Hofmeyra99b4272017-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
212DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]213DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]214DREF 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
218msc_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
221DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
222DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100[diff] [blame]223DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]224DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100[diff] [blame]225DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]226DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
227DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
228DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
229DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
230DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
231DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
232DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
233DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
234DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
235DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100[diff] [blame]236DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100[diff] [blame]237DMM -> SECURITY MODE CONTROL MSISDN:42342
238- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
239- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]240DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]241DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]242DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100[diff] [blame]243 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-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
246DMM <- SECURITY MODE COMPLETE MSISDN:42342
247DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
248DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
249DIUCS MSISDN:42342: tx CommonID 901700000010650
250- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
251DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
252DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
253DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
254DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
255DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
256DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
257DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
258DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]259DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
260DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]261DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
262DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
Neels Hofmeyra99b4272017-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
268DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
269DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]270DCC Unknown transaction ID 8, creating new trans.
271DCC (ti 08 sub MSISDN:42342 callref 80000001) New transaction
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]272DREF VLR subscr MSISDN:42342 usage increases to: 3
273DREF MSISDN:42342: MSC conn use + trans_cc == 3 (0xe)
274DMM MSISDN:42342: rx msg GSM48_MT_CC_SETUP: received_cm_service_request changes to false
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]275DCC (ti 08 sub MSISDN:42342) new state NULL -> INITIATED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]276DCC Subscriber MSISDN:42342 (42342) sends SETUP to 123
277DMNCC transmit message MNCC_SETUP_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]278DCC Sending 'MNCC_SETUP_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]279 MSC --> MNCC: callref 0x80000001: MNCC_SETUP_IND
280DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
281DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]282DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
283DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: CC
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]284DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc)
285- MNCC says that's fine
286DMNCC receive message MNCC_CALL_PROC_REQ
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]287DCC (ti 08 sub 42342) Received 'MNCC_CALL_PROC_REQ' from MNCC in state 1 (INITIATED)
288DCC (ti 08 sub MSISDN:42342) new state INITIATED -> MO_CALL_PROC
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]289DMSC 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
295DMNCC receive message MNCC_ALERT_REQ
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]296DCC (ti 08 sub 42342) Received 'MNCC_ALERT_REQ' from MNCC in state 3 (MO_CALL_PROC)
297DCC (ti 08 sub MSISDN:42342) new state MO_CALL_PROC -> CALL_DELIVERED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]298DMSC 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
301DMNCC receive message MNCC_SETUP_RSP
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]302DCC (ti 08 sub 42342) Received 'MNCC_SETUP_RSP' from MNCC in state 4 (CALL_DELIVERED)
303DCC starting timer T313 with 30 seconds
304DCC (ti 08 sub MSISDN:42342) new state CALL_DELIVERED -> CONNECT_IND
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]305DMSC 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
310DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
311DRLL Dispatching 04.08 message GSM48_MT_CC_CONNECT_ACK (0x3:0xf)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]312DCC stopping pending timer T313
313DCC (ti 08 sub MSISDN:42342) new state CONNECT_IND -> ACTIVE
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]314DMNCC transmit message MNCC_SETUP_COMPL_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]315DCC Sending 'MNCC_SETUP_COMPL_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]316 MSC --> MNCC: callref 0x80000001: MNCC_SETUP_COMPL_IND
317DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]318DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
319DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: CC
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]320DREF 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
327DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
328DRLL Dispatching 04.08 message GSM48_MT_CC_DISCONNECT (0x3:0x25)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]329DCC (ti 08 sub MSISDN:42342) new state ACTIVE -> DISCONNECT_IND
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]330DMNCC transmit message MNCC_DISC_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]331DCC Sending 'MNCC_DISC_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]332 MSC --> MNCC: callref 0x80000001: MNCC_DISC_IND
333DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]334DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
335DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: CC
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]336DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc)
337DMNCC receive message MNCC_REL_REQ
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]338DCC (ti 08 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 12 (DISCONNECT_IND)
339DCC starting timer T308 with 10 seconds
340DCC (ti 08 sub MSISDN:42342) new state DISCONNECT_IND -> RELEASE_REQ
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]341DMSC 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
345DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
346DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]347DCC stopping pending timer T308
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]348DMNCC transmit message MNCC_REL_CNF
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]349DCC Sending 'MNCC_REL_CNF' to MNCC.
Neels Hofmeyra99b4272017-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 Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]352DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]353DREF VLR subscr MSISDN:42342 usage decreases to: 2
354DREF MSISDN:42342: MSC conn use - trans_cc == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]355DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
356DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]357DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
358DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
359DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
360DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
361DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
362DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
363DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
364- Iu Release --RAN_UTRAN_IU--> MS
365DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
366DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
367DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
368DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
369DRLL subscr MSISDN:42342: Freeing subscriber connection
370DREF VLR subscr MSISDN:42342 usage decreases to: 1
371 llist_count(&net->subscr_conns) == 0
372DREF freeing VLR subscr MSISDN:42342
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]373===== test_call_mo: SUCCESS
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]374
375full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]376talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]377
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]378===== test_call_mt
Neels Hofmeyra99b4272017-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
383DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
384DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
385DREF unknown: MSC conn use + fsm == 2 (0x5)
386DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
387DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
388DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame^]389DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]390DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
391DMM LU/new-LAC: 23/23
392DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
393DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
394DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
395DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
396DREF VLR subscr unknown usage increases to: 1
397DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
398DVLR New subscr, IMSI: 901700000010650
399DREF VLR subscr IMSI:901700000010650 usage increases to: 2
400DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
401DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
402DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
403DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
404DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
405DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
406DVLR GSUP tx: 08010809710000000156f0
407GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
408DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]409DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]410DREF 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
414DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
415DREF VLR subscr IMSI:901700000010650 usage increases to: 2
416DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
417DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
418DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100[diff] [blame]419DVLR 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 Hofmeyra99b4272017-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
424DREF 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
430DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
431DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100[diff] [blame]432DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]433DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100[diff] [blame]434DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]435DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
436DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
437DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
438DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
439DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
440DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
441DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
442DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
443DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
Harald Welte71c51df2017-12-23 18:51:48 +0100[diff] [blame]444DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100[diff] [blame]445DMM -> SECURITY MODE CONTROL IMSI:901700000010650
446- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
447- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]448DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]449DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]450DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100[diff] [blame]451 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-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
454DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
455DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
456DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
457DIUCS IMSI:901700000010650: tx CommonID 901700000010650
458- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
459DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
460DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
461DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
462DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
463DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
464DVLR GSUP tx: 04010809710000000156f0
465GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
466DVLR 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
471DVLR GSUP rx 17: 10010809710000000156f00804032443f2
472DREF VLR subscr IMSI:901700000010650 usage increases to: 2
473DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +0100[diff] [blame]474DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]475DVLR GSUP tx: 12010809710000000156f0
476GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
477DREF 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
482DVLR GSUP rx 11: 06010809710000000156f0
483DREF VLR subscr MSISDN:42342 usage increases to: 2
484DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
485DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
486DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
487DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
488DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
489DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
490DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
491DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
492DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
493DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
494DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
495DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
496DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
497DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
498DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
499DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
500DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
501DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
502DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
503DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
504DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
505DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
506DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
507DVLR 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
509DREF 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
514msc_subscr_conn_is_accepted() == false
515- MS sends TMSI Realloc Complete
516 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
517DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
518DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
519DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
520DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
521DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
522DREF VLR subscr MSISDN:42342 usage increases to: 2
523DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
524DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
525DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
526DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
527DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
528DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
529DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
530DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]531DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]532DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
533DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]534DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
535DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
536DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
537DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
538DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
539DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
540DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
541DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
542- Iu Release --RAN_UTRAN_IU--> MS
543DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
544DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
545DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
546DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
547DRLL subscr MSISDN:42342: Freeing subscriber connection
548DREF 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
552DREF VLR subscr MSISDN:42342 usage increases to: 2
553 vsub != NULL == 1
554 strcmp(vsub->imsi, IMSI) == 0
555 vsub->lac == 23
556DREF VLR subscr MSISDN:42342 usage decreases to: 1
557---
558- after a while, MNCC asks us to setup a call, causing Paging
559DMNCC receive message MNCC_SETUP_REQ
560DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]561DCC (ti ff sub MSISDN:42342 callref 423) New transaction
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]562DREF VLR subscr MSISDN:42342 usage increases to: 3
563DMM 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
566DREF VLR subscr MSISDN:42342 usage increases to: 4
567DREF 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
573DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
574DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
575DRR PAGING RESPONSE: MI(IMSI)=901700000010650
576DREF unknown: MSC conn use + fsm == 2 (0x5)
577DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
578DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
579DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame^]580DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Updated ID from PAGING_RESP
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]581DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
582DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
583DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
584DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
585DREF VLR subscr MSISDN:42342 usage increases to: 4
586DREF VLR subscr MSISDN:42342 usage increases to: 5
587DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
588DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
589DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
590DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
591DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
592DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
Neels Hofmeyrfe718bc2018-03-11 01:24:33 +0100[diff] [blame]593DVLR 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 Hofmeyra99b4272017-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
598DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]599DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]600DREF 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
604DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
605DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100[diff] [blame]606DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]607DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100[diff] [blame]608DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]609DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
610DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
611DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
612DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
613DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
614DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
615DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
616DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
617DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
618DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Harald Welte71c51df2017-12-23 18:51:48 +0100[diff] [blame]619DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100[diff] [blame]620DMM -> SECURITY MODE CONTROL MSISDN:42342
621- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
622- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]623DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]624DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]625DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100[diff] [blame]626 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]627- MS sends SecurityModeControl acceptance, VLR accepts, sends CC Setup
628DMM <- SECURITY MODE COMPLETE MSISDN:42342
629DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
630DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
631DIUCS MSISDN:42342: tx CommonID 901700000010650
632- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
633DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
634DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
635DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
636DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
637DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
638DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
639DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
640DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]641DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
642DPAG Paging success for MSISDN:42342 (event=0)
643DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]644DCC Paging subscr 42342 succeeded!
Neels Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]645DREF MSISDN:42342: MSC conn use + trans_cc == 2 (0xc)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]646DCC starting timer T303 with 30 seconds
647DCC (ti 00 sub MSISDN:42342) new state NULL -> CALL_PRESENT
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]648DMSC 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
651DREF VLR subscr MSISDN:42342 usage decreases to: 3
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]652DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
653DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: connection still has active transaction: CC
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]654 paging_stopped == 1
655 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_CALL_CONF
Neels Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]656DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]657DRLL Dispatching 04.08 message GSM48_MT_CC_CALL_CONF (0x3:0x8)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]658DCC stopping pending timer T303
659DCC starting timer T310 with 30 seconds
660DCC (ti 00 sub MSISDN:42342) new state CALL_PRESENT -> MO_TERM_CALL_CONF
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]661 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x423
662DMNCC transmit message MNCC_CALL_CONF_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]663DCC Sending 'MNCC_CALL_CONF_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]664 MSC --> MNCC: callref 0x423: MNCC_CALL_CONF_IND
665DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
666DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]667DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
668DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: CC
Neels Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]669DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc)
Neels Hofmeyra99b4272017-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 Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]672DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]673DRLL Dispatching 04.08 message GSM48_MT_CC_ALERTING (0x3:0x1)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]674DCC stopping pending timer T310
675DCC starting timer T301 with 180 seconds
676DCC (ti 00 sub MSISDN:42342) new state MO_TERM_CALL_CONF -> CALL_RECEIVED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]677DMNCC transmit message MNCC_ALERT_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]678DCC Sending 'MNCC_ALERT_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]679 MSC --> MNCC: callref 0x423: MNCC_ALERT_IND
680DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]681DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
682DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: CC
Neels Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]683DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc)
Neels Hofmeyra99b4272017-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 Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]686DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]687DRLL Dispatching 04.08 message GSM48_MT_CC_CONNECT (0x3:0x7)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]688DCC stopping pending timer T301
689DCC (ti 00 sub MSISDN:42342) new state CALL_RECEIVED -> CONNECT_REQUEST
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]690DMNCC transmit message MNCC_SETUP_CNF
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]691DCC Sending 'MNCC_SETUP_CNF' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]692 MSC --> MNCC: callref 0x423: MNCC_SETUP_CNF
693DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]694DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
695DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: CC
Neels Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]696DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]697DMNCC receive message MNCC_SETUP_COMPL_REQ
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]698DCC (ti 00 sub 42342) Received 'MNCC_SETUP_COMPL_REQ' from MNCC in state 8 (CONNECT_REQUEST)
699DCC (ti 00 sub MSISDN:42342) new state CONNECT_REQUEST -> ACTIVE
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]700DMSC 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 Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]709DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]710DRLL Dispatching 04.08 message GSM48_MT_CC_DISCONNECT (0x3:0x25)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]711DCC (ti 00 sub MSISDN:42342) new state ACTIVE -> DISCONNECT_IND
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]712DMNCC transmit message MNCC_DISC_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]713DCC Sending 'MNCC_DISC_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]714 MSC --> MNCC: callref 0x423: MNCC_DISC_IND
715DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]716DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
717DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: CC
Neels Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]718DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]719DMNCC receive message MNCC_REL_REQ
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]720DCC (ti 00 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 12 (DISCONNECT_IND)
721DCC starting timer T308 with 10 seconds
722DCC (ti 00 sub MSISDN:42342) new state DISCONNECT_IND -> RELEASE_REQ
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]723DMSC 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 Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]727DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]728DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]729DCC stopping pending timer T308
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]730DMNCC transmit message MNCC_REL_CNF
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]731DCC Sending 'MNCC_REL_CNF' to MNCC.
Neels Hofmeyra99b4272017-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 Hofmeyr12e17be2018-03-12 23:59:37 +0100[diff] [blame]734DCC (ti 00 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]735DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]736DREF MSISDN:42342: MSC conn use - trans_cc == 2 (0x6)
Neels Hofmeyre9e2f5c2018-03-15 13:26:43 +0100[diff] [blame]737DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
738DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]739DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
740DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
741DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
742DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
743DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
744DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
745DMM 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 Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]747DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]748DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
749DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyr82be67d2017-11-22 15:43:03 +0100[diff] [blame]750DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
751DRLL subscr MSISDN:42342: Freeing subscriber connection
752DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]753 llist_count(&net->subscr_conns) == 0
754DREF freeing VLR subscr MSISDN:42342
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100[diff] [blame]755===== test_call_mt: SUCCESS
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]756
757full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]758talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]759
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]760===== test_call_mo_to_unknown
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
765DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
766DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
767DREF unknown: MSC conn use + fsm == 2 (0x5)
768DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
769DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
770DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame^]771DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]772DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
773DMM LU/new-LAC: 23/23
774DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
775DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
776DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
777DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
778DREF VLR subscr unknown usage increases to: 1
779DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
780DVLR New subscr, IMSI: 901700000010650
781DREF VLR subscr IMSI:901700000010650 usage increases to: 2
782DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
783DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
784DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
785DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
786DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
787DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
788DVLR GSUP tx: 08010809710000000156f0
789GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
790DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
791DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
792DREF 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
796DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
797DREF VLR subscr IMSI:901700000010650 usage increases to: 2
798DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
799DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
800DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
801DVLR 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
806DREF 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
812DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
813DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
814DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
815DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
816DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
817DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
818DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
819DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
820DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
821DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
822DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
823DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
824DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
825DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
826DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
827DMM -> SECURITY MODE CONTROL IMSI:901700000010650
828- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
829- ...ik=27497388b6cb044648f396aa155b95ef
830DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
831DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
832DREF 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
836DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
837DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
838DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
839DIUCS IMSI:901700000010650: tx CommonID 901700000010650
840- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
841DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
842DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
843DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
844DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
845DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
846DVLR GSUP tx: 04010809710000000156f0
847GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
848DVLR 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
853DVLR GSUP rx 17: 10010809710000000156f00804032443f2
854DREF VLR subscr IMSI:901700000010650 usage increases to: 2
855DVLR IMSI:901700000010650 has MSISDN:42342
856DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
857DVLR GSUP tx: 12010809710000000156f0
858GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
859DREF 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
864DVLR GSUP rx 11: 06010809710000000156f0
865DREF VLR subscr MSISDN:42342 usage increases to: 2
866DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
867DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
868DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
869DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
870DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
871DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
872DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
873DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
874DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
875DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
876DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
877DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
878DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
879DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
880DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
881DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
882DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
883DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
884DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
885DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
886DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
887DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
888DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
889DVLR 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
891DREF 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
896msc_subscr_conn_is_accepted() == false
897- MS sends TMSI Realloc Complete
898 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
899DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
900DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
901DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
902DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
903DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
904DREF VLR subscr MSISDN:42342 usage increases to: 2
905DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
906DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
907DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
908DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
909DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
910DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
911DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
912DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]913DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
914DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
915DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
916DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
917DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
918DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
919DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
920DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
921DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
922DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
923DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
924- Iu Release --RAN_UTRAN_IU--> MS
925DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
926DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
927DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
928DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
929DRLL subscr MSISDN:42342: Freeing subscriber connection
930DREF 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
934DREF VLR subscr MSISDN:42342 usage increases to: 2
935 vsub != NULL == 1
936 strcmp(vsub->imsi, IMSI) == 0
937 vsub->lac == 23
938DREF VLR subscr MSISDN:42342 usage decreases to: 1
939---
940- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
941 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_CM_SERV_REQ
942 new conn
943DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
944DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
945DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
946DREF unknown: MSC conn use + fsm == 2 (0x5)
947DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
948DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
949DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame^]950DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]951DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
952DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
953DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
954DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
955DREF VLR subscr MSISDN:42342 usage increases to: 2
956DREF VLR subscr MSISDN:42342 usage increases to: 3
957DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
958DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
959DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
960DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
961DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
962DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
963DVLR 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)
964- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
965- ...rand=c187a53a5e6b9d573cac7c74451fd46d
966- ...autn=1843a645b98d00005b2d666af46c45d9
967- ...expecting res=7db47cf7f81e4dc7
968DREF VLR subscr MSISDN:42342 usage decreases to: 2
969DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
970DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
971 cm_service_result_sent == 0
972 auth_request_sent == 1
973- needs auth, not yet accepted
974msc_subscr_conn_is_accepted() == false
975- MS sends Authen Response, VLR accepts and sends SecurityModeControl
976 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
977DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
978DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
979DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
980DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
981DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
982DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
983DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
984DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
985DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
986DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
987DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
988DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
989DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
990DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
991DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
992DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
993DMM -> SECURITY MODE CONTROL MSISDN:42342
994- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
995- ...ik=1159ec926a50e98c034a6b7d7c9f418d
996DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
997DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
998DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
999 security_mode_ctrl_sent == 1
1000 cm_service_result_sent == 0
1001- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
1002DMM <- SECURITY MODE COMPLETE MSISDN:42342
1003DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
1004DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
1005DIUCS MSISDN:42342: tx CommonID 901700000010650
1006- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
1007DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
1008DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
1009DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
1010DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
1011DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1012DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
1013DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1014DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1015DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1016DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
1017DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1018DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
1019 cm_service_result_sent == 0
1020---
1021- a call is initiated
1022- SETUP gets forwarded to MNCC
1023 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_SETUP
1024DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
1025DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1026DCC Unknown transaction ID 8, creating new trans.
1027DCC (ti 08 sub MSISDN:42342 callref 80000002) New transaction
1028DREF VLR subscr MSISDN:42342 usage increases to: 3
1029DREF MSISDN:42342: MSC conn use + trans_cc == 3 (0xe)
1030DMM MSISDN:42342: rx msg GSM48_MT_CC_SETUP: received_cm_service_request changes to false
1031DCC (ti 08 sub MSISDN:42342) new state NULL -> INITIATED
1032DCC Subscriber MSISDN:42342 (42342) sends SETUP to 123
1033DMNCC transmit message MNCC_SETUP_IND
1034DCC Sending 'MNCC_SETUP_IND' to MNCC.
1035 MSC --> MNCC: callref 0x80000002: MNCC_SETUP_IND
1036DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1037DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
1038DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1039DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: CC
1040DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc)
1041- MNCC says that's fine
1042DMNCC receive message MNCC_CALL_PROC_REQ
1043DCC (ti 08 sub 42342) Received 'MNCC_CALL_PROC_REQ' from MNCC in state 1 (INITIATED)
1044DCC (ti 08 sub MSISDN:42342) new state INITIATED -> MO_CALL_PROC
1045DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1046- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CALL_PROC: 8302
1047- DTAP matches expected message
1048 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x80000002
1049- But the other side's MSISDN could not be resolved, MNCC tells us to cancel
1050DMNCC receive message MNCC_REL_REQ
1051DCC (ti 08 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 3 (MO_CALL_PROC)
1052DCC starting timer T308 with 10 seconds
1053DCC (ti 08 sub MSISDN:42342) new state MO_CALL_PROC -> RELEASE_REQ
1054DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1055- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d
1056- DTAP matches expected message
1057- Total time passed: 10.000023 s
1058DCC starting timer T308 with 10 seconds
1059DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1060- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d
1061- DTAP matches expected message
1062 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_RELEASE_COMPL
1063DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
1064DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a)
1065DCC stopping pending timer T308
1066DMNCC transmit message MNCC_REL_CNF
1067DCC Sending 'MNCC_REL_CNF' to MNCC.
1068 MSC --> MNCC: callref 0x80000002: MNCC_REL_CNF
1069 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x0
1070DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
1071DREF VLR subscr MSISDN:42342 usage decreases to: 2
1072DREF MSISDN:42342: MSC conn use - trans_cc == 2 (0x6)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1073DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1074DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
1075DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1076DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1077DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1078DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1079DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
1080DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
1081DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
1082- Iu Release --RAN_UTRAN_IU--> MS
1083DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
1084DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1085DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1086DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
1087DRLL subscr MSISDN:42342: Freeing subscriber connection
1088DREF VLR subscr MSISDN:42342 usage decreases to: 1
1089 llist_count(&net->subscr_conns) == 0
1090DREF freeing VLR subscr MSISDN:42342
1091===== test_call_mo_to_unknown: SUCCESS
1092
1093full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1094talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1095
1096===== test_call_mo_to_unknown_timeout
1097- Total time passed: 0.000000 s
1098- Location Update request causes a GSUP Send Auth Info request to HLR
1099 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1100 new conn
1101DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1102DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
1103DREF unknown: MSC conn use + fsm == 2 (0x5)
1104DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1105DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1106DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame^]1107DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Updated ID from LU
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1108DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1109DMM LU/new-LAC: 23/23
1110DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
1111DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
1112DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
1113DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
1114DREF VLR subscr unknown usage increases to: 1
1115DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1116DVLR New subscr, IMSI: 901700000010650
1117DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1118DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1119DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1120DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1121DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1122DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
1123DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1124DVLR GSUP tx: 08010809710000000156f0
1125GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
1126DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
1127DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
1128DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
1129 lu_result_sent == 0
1130- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1131<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1132DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1133DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1134DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
1135DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
1136DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
1137DVLR 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)
1138- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1139- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1140- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1141- ...expecting res=e229c19e791f2e41
1142DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1143<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1144 auth_request_sent == 1
1145 lu_result_sent == 0
1146- MS sends Authen Response, VLR accepts and sends SecurityModeControl
1147 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
1148DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
1149DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1150DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
1151DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
1152DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
1153DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
1154DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1155DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1156DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1157DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
1158DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1159DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1160DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1161DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1162DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
1163DMM -> SECURITY MODE CONTROL IMSI:901700000010650
1164- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1165- ...ik=27497388b6cb044648f396aa155b95ef
1166DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
1167DMM IMSI:901700000010650: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
1168DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
1169 security_mode_ctrl_sent == 1
1170 lu_result_sent == 0
1171- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
1172DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
1173DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1174DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
1175DIUCS IMSI:901700000010650: tx CommonID 901700000010650
1176- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
1177DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1178DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1179DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1180DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1181DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
1182DVLR GSUP tx: 04010809710000000156f0
1183GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
1184DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
1185 gsup_tx_confirmed == 1
1186 lu_result_sent == 0
1187- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1188<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1189DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1190DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1191DVLR IMSI:901700000010650 has MSISDN:42342
1192DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
1193DVLR GSUP tx: 12010809710000000156f0
1194GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1195DREF VLR subscr MSISDN:42342 usage decreases to: 1
1196<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1197 lu_result_sent == 0
1198- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1199<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1200DVLR GSUP rx 11: 06010809710000000156f0
1201DREF VLR subscr MSISDN:42342 usage increases to: 2
1202DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1203DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1204DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1205DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1206DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1207DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1208DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1209DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1210DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1211DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1212DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
1213DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1214DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1215DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1216DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
1217DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1218DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1219DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1220DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
1221DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1222DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1223DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1224DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1225DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
1226- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
1227DREF VLR subscr MSISDN:42342 usage decreases to: 1
1228<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1229 lu_result_sent == 1
1230- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1231 llist_count(&net->subscr_conns) == 1
1232msc_subscr_conn_is_accepted() == false
1233- MS sends TMSI Realloc Complete
1234 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
1235DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
1236DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
1237DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
1238DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1239DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
1240DREF VLR subscr MSISDN:42342 usage increases to: 2
1241DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1242DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1243DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1244DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
1245DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1246DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1247DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1248DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1249DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1250DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1251DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: releasing conn
1252DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
1253DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1254DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1255DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1256DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1257DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
1258DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
1259DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
1260- Iu Release --RAN_UTRAN_IU--> MS
1261DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
1262DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1263DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
1264DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
1265DRLL subscr MSISDN:42342: Freeing subscriber connection
1266DREF VLR subscr MSISDN:42342 usage decreases to: 1
1267 iu_release_sent == 1
1268- LU was successful, and the conn has already been closed
1269 llist_count(&net->subscr_conns) == 0
1270DREF VLR subscr MSISDN:42342 usage increases to: 2
1271 vsub != NULL == 1
1272 strcmp(vsub->imsi, IMSI) == 0
1273 vsub->lac == 23
1274DREF VLR subscr MSISDN:42342 usage decreases to: 1
1275---
1276- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
1277 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_CM_SERV_REQ
1278 new conn
1279DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
1280DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
1281DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
1282DREF unknown: MSC conn use + fsm == 2 (0x5)
1283DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
1284DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
1285DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
Neels Hofmeyr16c42b52018-04-02 12:26:16 +0200[diff] [blame^]1286DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Updated ID from CM_SERVICE_REQ
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1287DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
1288DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
1289DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
1290DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
1291DREF VLR subscr MSISDN:42342 usage increases to: 2
1292DREF VLR subscr MSISDN:42342 usage increases to: 3
1293DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1294DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1295DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1296DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
1297DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1298DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
1299DVLR 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)
1300- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
1301- ...rand=c187a53a5e6b9d573cac7c74451fd46d
1302- ...autn=1843a645b98d00005b2d666af46c45d9
1303- ...expecting res=7db47cf7f81e4dc7
1304DREF VLR subscr MSISDN:42342 usage decreases to: 2
1305DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
1306DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
1307 cm_service_result_sent == 0
1308 auth_request_sent == 1
1309- needs auth, not yet accepted
1310msc_subscr_conn_is_accepted() == false
1311- MS sends Authen Response, VLR accepts and sends SecurityModeControl
1312 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
1313DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
1314DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1315DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
1316DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
1317DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
1318DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
1319DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
1320DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1321DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1322DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
1323DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1324DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1325DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
1326DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
1327DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1328DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
1329DMM -> SECURITY MODE CONTROL MSISDN:42342
1330- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1331- ...ik=1159ec926a50e98c034a6b7d7c9f418d
1332DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
1333DMM MSISDN:42342: subscr_conn_release_when_unused: conn still being established (SUBSCR_CONN_S_NEW)
1334DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
1335 security_mode_ctrl_sent == 1
1336 cm_service_result_sent == 0
1337- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
1338DMM <- SECURITY MODE COMPLETE MSISDN:42342
1339DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
1340DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
1341DIUCS MSISDN:42342: tx CommonID 901700000010650
1342- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
1343DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
1344DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
1345DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
1346DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
1347DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
1348DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
1349DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
1350DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1351DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
1352DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
1353DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1354DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_release_when_unused: still awaiting first request after a CM Service Request
1355 cm_service_result_sent == 0
1356---
1357- a call is initiated
1358- SETUP gets forwarded to MNCC
1359 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_SETUP
1360DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
1361DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1362DCC Unknown transaction ID 8, creating new trans.
1363DCC (ti 08 sub MSISDN:42342 callref 80000003) New transaction
1364DREF VLR subscr MSISDN:42342 usage increases to: 3
1365DREF MSISDN:42342: MSC conn use + trans_cc == 3 (0xe)
1366DMM MSISDN:42342: rx msg GSM48_MT_CC_SETUP: received_cm_service_request changes to false
1367DCC (ti 08 sub MSISDN:42342) new state NULL -> INITIATED
1368DCC Subscriber MSISDN:42342 (42342) sends SETUP to 123
1369DMNCC transmit message MNCC_SETUP_IND
1370DCC Sending 'MNCC_SETUP_IND' to MNCC.
1371 MSC --> MNCC: callref 0x80000003: MNCC_SETUP_IND
1372DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1373DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
1374DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1375DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: connection still has active transaction: CC
1376DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc)
1377- MNCC says that's fine
1378DMNCC receive message MNCC_CALL_PROC_REQ
1379DCC (ti 08 sub 42342) Received 'MNCC_CALL_PROC_REQ' from MNCC in state 1 (INITIATED)
1380DCC (ti 08 sub MSISDN:42342) new state INITIATED -> MO_CALL_PROC
1381DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1382- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CALL_PROC: 8302
1383- DTAP matches expected message
1384 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x80000003
1385- But the other side's MSISDN could not be resolved, MNCC tells us to cancel
1386DMNCC receive message MNCC_REL_REQ
1387DCC (ti 08 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 3 (MO_CALL_PROC)
1388DCC starting timer T308 with 10 seconds
1389DCC (ti 08 sub MSISDN:42342) new state MO_CALL_PROC -> RELEASE_REQ
1390DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1391- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d
1392- DTAP matches expected message
1393- Despite our repeated CC Release Requests, the MS does not respond anymore
1394- Total time passed: 10.000023 s
1395DCC starting timer T308 with 10 seconds
1396DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1397- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d
1398- DTAP matches expected message
1399- The CC Release times out and we still properly clear the conn
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1400- Total time passed: 20.000046 s
1401 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x80000003
1402DMNCC transmit message MNCC_REL_CNF
1403DCC Sending 'MNCC_REL_CNF' to MNCC.
1404 MSC --> MNCC: callref 0x80000003: MNCC_REL_CNF
1405DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
1406DREF VLR subscr MSISDN:42342 usage decreases to: 2
1407DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x4)
Neels Hofmeyrd6a769b2018-03-12 23:59:07 +0100[diff] [blame]1408DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_RELEASE_WHEN_UNUSED
1409DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: subscr_conn_fsm_release_when_unused: releasing conn
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1410DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
1411DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1412DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1413DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
1414DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
1415DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
1416DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
1417- Iu Release --RAN_UTRAN_IU--> MS
1418DREF MSISDN:42342: MSC conn use - fsm == 0 (0x0)
1419DRLL subscr MSISDN:42342: Freeing subscriber connection
1420DREF VLR subscr MSISDN:42342 usage decreases to: 1
1421DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1422DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyrd6a769b2018-03-12 23:59:07 +0100[diff] [blame]1423 llist_count(&net->subscr_conns) == 0
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1424DREF freeing VLR subscr MSISDN:42342
1425===== test_call_mo_to_unknown_timeout: SUCCESS
1426
1427full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1428talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +0100[diff] [blame]1429
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]1430full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200[diff] [blame]1431talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame]1432