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