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