Gitiles
Code Review Sign In
gerrit.osmocom.org / osmo-msc / a99b42709a09b1b822da0e431bf3308da7b7a295 / . / tests / msc_vlr / msc_vlr_test_call.err
blob: 6fd9288537477a23dbf88619fb94f57e78534934 [file] [log] [blame]
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100[diff] [blame^]1===== test_call_mo
2- Total time passed: 0.000000 s
3- Location Update request causes a GSUP Send Auth Info request to HLR
4 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
5 new conn
6DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
7DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
8DREF unknown: MSC conn use + fsm == 2 (0x5)
9DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
10DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
11DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
12DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
13DMM LU/new-LAC: 23/23
14DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
15DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
16DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
17DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
18DREF VLR subscr unknown usage increases to: 1
19DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
20DVLR New subscr, IMSI: 901700000010650
21DREF VLR subscr IMSI:901700000010650 usage increases to: 2
22DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
23DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
24DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
25DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
26DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
27DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
28DVLR GSUP tx: 08010809710000000156f0
29GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
30DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
31DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
32DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
33 lu_result_sent == 0
34- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
35<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
36DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
37DREF VLR subscr IMSI:901700000010650 usage increases to: 2
38DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
39DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
40DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
41DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
42- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
43- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
44- ...autn=8704f5ba55f30000d2ee44b22c8ea919
45- ...expecting res=e229c19e791f2e41
46DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
47<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
48 auth_request_sent == 1
49 lu_result_sent == 0
50- MS sends Authen Response, VLR accepts and sends SecurityModeControl
51 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
52DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
53DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
54DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
55DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
56DVLR SUBSCR(IMSI:901700000010650) received res: e2 29 c1 9e 79 1f 2e 41
57DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
58DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
59DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
60DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
61DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
62DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
63DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
64DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
65DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
66- sending SecurityModeControl for IMSI:901700000010650
67DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
68DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
69DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
70 cipher_mode_cmd_sent == 1
71 lu_result_sent == 0
72- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
73DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
74DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
75DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
76DIUCS IMSI:901700000010650: tx CommonID 901700000010650
77- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
78DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
79DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
80DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
81DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
82DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
83DVLR GSUP tx: 04010809710000000156f0
84GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
85DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
86 gsup_tx_confirmed == 1
87 lu_result_sent == 0
88- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
89<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
90DVLR GSUP rx 17: 10010809710000000156f00804032443f2
91DREF VLR subscr IMSI:901700000010650 usage increases to: 2
92DVLR IMSI:901700000010650 has MSISDN:42342
93DVLR GSUP tx: 12010809710000000156f0
94GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
95DREF VLR subscr MSISDN:42342 usage decreases to: 1
96<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
97 lu_result_sent == 0
98- HLR also sends GSUP _UPDATE_LOCATION_RESULT
99<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
100DVLR GSUP rx 11: 06010809710000000156f0
101DREF VLR subscr MSISDN:42342 usage increases to: 2
102DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
103DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
104DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
105DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
106DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
107DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
108DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
109DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
110DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
111DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
112DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
113DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
114DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
115DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
116DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
117DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
118DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
119DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
120DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
121DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
122DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
123DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
124DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
125DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
126- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
127DREF VLR subscr MSISDN:42342 usage decreases to: 1
128<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
129 lu_result_sent == 1
130- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
131 llist_count(&net->subscr_conns) == 1
132msc_subscr_conn_is_accepted() == false
133- MS sends TMSI Realloc Complete
134 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
135DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
136DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
137DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
138DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
139DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
140DREF VLR subscr MSISDN:42342 usage increases to: 2
141DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
142DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
143DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
144DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
145DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
146DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
147DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
148DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
149DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
150DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
151DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
152DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
153DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
154DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
155DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
156DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
157DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
158DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
159DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
160DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
161- Iu Release --RAN_UTRAN_IU--> MS
162DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
163DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
164DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
165DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
166DRLL subscr MSISDN:42342: Freeing subscriber connection
167DREF VLR subscr MSISDN:42342 usage decreases to: 1
168 iu_release_sent == 1
169- LU was successful, and the conn has already been closed
170 llist_count(&net->subscr_conns) == 0
171DREF VLR subscr MSISDN:42342 usage increases to: 2
172 vsub != NULL == 1
173 strcmp(vsub->imsi, IMSI) == 0
174 vsub->lac == 23
175DREF VLR subscr MSISDN:42342 usage decreases to: 1
176---
177- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
178 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_CM_SERV_REQ
179 new conn
180DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
181DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
182DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
183DREF unknown: MSC conn use + fsm == 2 (0x5)
184DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
185DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
186DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
187DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
188DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
189DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
190DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
191DREF VLR subscr MSISDN:42342 usage increases to: 2
192DREF VLR subscr MSISDN:42342 usage increases to: 3
193DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
194DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
195DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
196DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
197DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
198DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
199DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
200- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
201- ...rand=c187a53a5e6b9d573cac7c74451fd46d
202- ...autn=1843a645b98d00005b2d666af46c45d9
203- ...expecting res=7db47cf7f81e4dc7
204DREF VLR subscr MSISDN:42342 usage decreases to: 2
205DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
206DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
207 cm_service_result_sent == 0
208 auth_request_sent == 1
209- needs auth, not yet accepted
210msc_subscr_conn_is_accepted() == false
211- MS sends Authen Response, VLR accepts and sends SecurityModeControl
212 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
213DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
214DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
215DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
216DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
217DVLR SUBSCR(MSISDN:42342) received res: 7d b4 7c f7 f8 1e 4d c7
218DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
219DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
220DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
221DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
222DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
223DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
224DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
225DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
226DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
227DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
228- sending SecurityModeControl for MSISDN:42342
229DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
230DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
231DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
232 cipher_mode_cmd_sent == 1
233 cm_service_result_sent == 0
234- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
235DMM <- SECURITY MODE COMPLETE MSISDN:42342
236DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
237DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
238DIUCS MSISDN:42342: tx CommonID 901700000010650
239- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
240DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
241DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
242DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
243DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
244DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
245DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
246DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
247DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
248DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_CM_SERVICE_REQ
249DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
250DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: received_cm_service_request = true
251DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
252DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: still awaiting first request after a CM Service Request
253 cm_service_result_sent == 0
254---
255- a call is initiated
256- SETUP gets forwarded to MNCC
257 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_SETUP
258DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
259DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
260DREF VLR subscr MSISDN:42342 usage increases to: 3
261DREF MSISDN:42342: MSC conn use + trans_cc == 3 (0xe)
262DMM MSISDN:42342: rx msg GSM48_MT_CC_SETUP: received_cm_service_request changes to false
263DCC Subscriber MSISDN:42342 (42342) sends SETUP to 123
264DMNCC transmit message MNCC_SETUP_IND
265 MSC --> MNCC: callref 0x80000001: MNCC_SETUP_IND
266DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
267DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
268DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
269DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC
270DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc)
271- MNCC says that's fine
272DMNCC receive message MNCC_CALL_PROC_REQ
273DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
274- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CALL_PROC: 8302
275- DTAP matches expected message
276 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x80000001
277- Total time passed: 1.000023 s
278- The other call leg got established (not shown here), MNCC tells us so
279DMNCC receive message MNCC_ALERT_REQ
280DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
281- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_ALERTING: 8301
282- DTAP matches expected message
283DMNCC receive message MNCC_SETUP_RSP
284DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
285- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CONNECT: 8307
286- DTAP matches expected message
287- Total time passed: 2.000046 s
288 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_CONNECT_ACK
289DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
290DRLL Dispatching 04.08 message GSM48_MT_CC_CONNECT_ACK (0x3:0xf)
291DMNCC transmit message MNCC_SETUP_COMPL_IND
292 MSC --> MNCC: callref 0x80000001: MNCC_SETUP_COMPL_IND
293DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
294DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
295DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC
296DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc)
297---
298- RTP stream goes ahead, not shown here.
299- Total time passed: 125.000091 s
300---
301- Call ends
302 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_DISCONNECT
303DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
304DRLL Dispatching 04.08 message GSM48_MT_CC_DISCONNECT (0x3:0x25)
305DMNCC transmit message MNCC_DISC_IND
306 MSC --> MNCC: callref 0x80000001: MNCC_DISC_IND
307DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
308DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
309DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC
310DREF MSISDN:42342: MSC conn use - dtap == 2 (0xc)
311DMNCC receive message MNCC_REL_REQ
312DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
313- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d
314- DTAP matches expected message
315 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_RELEASE_COMPL
316DREF MSISDN:42342: MSC conn use + dtap == 3 (0xe)
317DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a)
318DMNCC transmit message MNCC_REL_CNF
319 MSC --> MNCC: callref 0x80000001: MNCC_REL_CNF
320 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x0
321DREF VLR subscr MSISDN:42342 usage decreases to: 2
322DREF MSISDN:42342: MSC conn use - trans_cc == 2 (0x6)
323DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
324DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
325DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
326DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
327DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
328DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
329DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
330DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
331DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
332DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
333- Iu Release --RAN_UTRAN_IU--> MS
334DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
335DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
336DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
337DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
338DRLL subscr MSISDN:42342: Freeing subscriber connection
339DREF VLR subscr MSISDN:42342 usage decreases to: 1
340 llist_count(&net->subscr_conns) == 0
341DREF freeing VLR subscr MSISDN:42342
342===== test_call_mo: SUCCESS
343
344full talloc report on 'msgb' (total 0 bytes in 1 blocks)
345talloc_total_blocks(tall_bsc_ctx) == 9
346
347===== test_call_mt
348- Total time passed: 0.000000 s
349- Location Update request causes a GSUP Send Auth Info request to HLR
350 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
351 new conn
352DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
353DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
354DREF unknown: MSC conn use + fsm == 2 (0x5)
355DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
356DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
357DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
358DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
359DMM LU/new-LAC: 23/23
360DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Allocated
361DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(901700000010650)
362DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
363DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
364DREF VLR subscr unknown usage increases to: 1
365DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
366DVLR New subscr, IMSI: 901700000010650
367DREF VLR subscr IMSI:901700000010650 usage increases to: 2
368DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
369DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
370DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
371DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
372DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(901700000010650)
373DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
374DVLR GSUP tx: 08010809710000000156f0
375GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
376DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
377DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
378DREF IMSI:901700000010650: MSC conn use - compl_l3 == 1 (0x4)
379 lu_result_sent == 0
380- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
381<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
382DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
383DREF VLR subscr IMSI:901700000010650 usage increases to: 2
384DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
385DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
386DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
387DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0
388- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
389- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
390- ...autn=8704f5ba55f30000d2ee44b22c8ea919
391- ...expecting res=e229c19e791f2e41
392DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
393<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
394 auth_request_sent == 1
395 lu_result_sent == 0
396- MS sends Authen Response, VLR accepts and sends SecurityModeControl
397 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
398DREF IMSI:901700000010650: MSC conn use + dtap == 2 (0x6)
399DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
400DMM IMSI:901700000010650: MM R99 AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
401DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
402DVLR SUBSCR(IMSI:901700000010650) received res: e2 29 c1 9e 79 1f 2e 41
403DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
404DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
405DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
406DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
407DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(901700000010650)
408DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
409DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
410DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
411DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
412- sending SecurityModeControl for IMSI:901700000010650
413DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
414DMM IMSI:901700000010650: bump: conn still being established (SUBSCR_CONN_S_NEW)
415DREF IMSI:901700000010650: MSC conn use - dtap == 1 (0x4)
416 cipher_mode_cmd_sent == 1
417 lu_result_sent == 0
418- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
419DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
420DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
421DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
422DIUCS IMSI:901700000010650: tx CommonID 901700000010650
423- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
424DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
425DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
426DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
427DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
428DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
429DVLR GSUP tx: 04010809710000000156f0
430GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0
431DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
432 gsup_tx_confirmed == 1
433 lu_result_sent == 0
434- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
435<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
436DVLR GSUP rx 17: 10010809710000000156f00804032443f2
437DREF VLR subscr IMSI:901700000010650 usage increases to: 2
438DVLR IMSI:901700000010650 has MSISDN:42342
439DVLR GSUP tx: 12010809710000000156f0
440GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
441DREF VLR subscr MSISDN:42342 usage decreases to: 1
442<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
443 lu_result_sent == 0
444- HLR also sends GSUP _UPDATE_LOCATION_RESULT
445<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
446DVLR GSUP rx 11: 06010809710000000156f0
447DREF VLR subscr MSISDN:42342 usage increases to: 2
448DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
449DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
450DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
451DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
452DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
453DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
454DVLR upd_hlr_vlr_fsm(901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
455DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
456DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
457DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
458DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(901700000010650)
459DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
460DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
461DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
462DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(901700000010650)
463DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
464DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
465DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
466DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(901700000010650)
467DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
468DVLR sub_pres_vlr_fsm(901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
469DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
470DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
471DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
472- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
473DREF VLR subscr MSISDN:42342 usage decreases to: 1
474<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
475 lu_result_sent == 1
476- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
477 llist_count(&net->subscr_conns) == 1
478msc_subscr_conn_is_accepted() == false
479- MS sends TMSI Realloc Complete
480 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
481DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
482DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
483DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
484DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
485DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
486DREF VLR subscr MSISDN:42342 usage increases to: 2
487DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
488DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
489DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
490DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(901700000010650)
491DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
492DVLR lu_compl_vlr_fsm(901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
493DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
494DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
495DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_LU
496DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
497DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
498DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: releasing conn
499DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASED
500DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
501DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
502DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
503DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
504DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Freeing instance
505DVLR vlr_lu_fsm(901700000010650){VLR_ULA_S_DONE}: Deallocated
506DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
507- Iu Release --RAN_UTRAN_IU--> MS
508DREF MSISDN:42342: MSC conn use - fsm == 1 (0x2)
509DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
510DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
511DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0)
512DRLL subscr MSISDN:42342: Freeing subscriber connection
513DREF VLR subscr MSISDN:42342 usage decreases to: 1
514 iu_release_sent == 1
515- LU was successful, and the conn has already been closed
516 llist_count(&net->subscr_conns) == 0
517DREF VLR subscr MSISDN:42342 usage increases to: 2
518 vsub != NULL == 1
519 strcmp(vsub->imsi, IMSI) == 0
520 vsub->lac == 23
521DREF VLR subscr MSISDN:42342 usage decreases to: 1
522---
523- after a while, MNCC asks us to setup a call, causing Paging
524DMNCC receive message MNCC_SETUP_REQ
525DREF VLR subscr MSISDN:42342 usage increases to: 2
526DREF VLR subscr MSISDN:42342 usage increases to: 3
527DMM Subscriber MSISDN:42342 not paged yet, start paging.
528 RAN_UTRAN_IU sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23
529 strcmp(paging_expecting_imsi, imsi) == 0
530DREF VLR subscr MSISDN:42342 usage increases to: 4
531DREF VLR subscr MSISDN:42342 usage decreases to: 3
532 paging_sent == 1
533 paging_stopped == 0
534- MS replies with Paging Response, and VLR sends Auth Request
535 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_RR_PAG_RESP
536 new conn
537DREF unknown: MSC conn use + compl_l3 == 1 (0x1)
538DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
539DRR PAGING RESPONSE: MI(IMSI)=901700000010650
540DREF unknown: MSC conn use + fsm == 2 (0x5)
541DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Allocated
542DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: Received Event SUBSCR_CONN_E_START
543DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_INIT}: state_chg to SUBSCR_CONN_S_NEW
544DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Allocated
545DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(901700000010650)
546DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
547DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
548DREF VLR subscr MSISDN:42342 usage increases to: 4
549DREF VLR subscr MSISDN:42342 usage increases to: 5
550DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
551DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
552DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
553DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(901700000010650)
554DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
555DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
556DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=1
557- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
558- ...rand=c187a53a5e6b9d573cac7c74451fd46d
559- ...autn=1843a645b98d00005b2d666af46c45d9
560- ...expecting res=7db47cf7f81e4dc7
561DREF VLR subscr MSISDN:42342 usage decreases to: 4
562DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
563DREF MSISDN:42342: MSC conn use - compl_l3 == 1 (0x4)
564 auth_request_sent == 1
565- MS sends Authen Response, VLR accepts and sends SecurityModeControl
566 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
567DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
568DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
569DMM MSISDN:42342: MM R99 AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
570DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
571DVLR SUBSCR(MSISDN:42342) received res: 7d b4 7c f7 f8 1e 4d c7
572DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
573DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result VLR_AUTH_RES_PASSED
574DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
575DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
576DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(901700000010650)
577DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
578DVLR VLR_Authenticate(901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
579DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
580DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: got VLR_AUTH_RES_PASSED
581DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
582- sending SecurityModeControl for MSISDN:42342
583DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
584DMM MSISDN:42342: bump: conn still being established (SUBSCR_CONN_S_NEW)
585DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
586 cipher_mode_cmd_sent == 1
587- MS sends SecurityModeControl acceptance, VLR accepts, sends CC Setup
588DMM <- SECURITY MODE COMPLETE MSISDN:42342
589DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
590DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
591DIUCS MSISDN:42342: tx CommonID 901700000010650
592- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
593DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
594DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
595DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
596DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
597DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(VLR_PR_ARQ_RES_PASSED)
598DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
599DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Process Access Request result: VLR_PR_ARQ_RES_PASSED
600DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_ACCEPTED
601DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: SUBSCR_CONN_FROM_PAGING_RESP
602DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_ACCEPTED
603DPAG Paging success for MSISDN:42342 (event=0)
604DPAG Calling paging cbfn.
605DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
606- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_SETUP: 0305
607- DTAP matches expected message
608DREF VLR subscr MSISDN:42342 usage decreases to: 3
609DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_BUMP
610DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: bump: connection still has active transaction: GSM48_PDISC_CC
611 paging_stopped == 1
612 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_CALL_CONF
613DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
614DRLL Dispatching 04.08 message GSM48_MT_CC_CALL_CONF (0x3:0x8)
615 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x423
616DMNCC transmit message MNCC_CALL_CONF_IND
617 MSC --> MNCC: callref 0x423: MNCC_CALL_CONF_IND
618DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
619DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
620DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
621DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC
622DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
623- Total time passed: 1.000023 s
624 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_ALERTING
625DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
626DRLL Dispatching 04.08 message GSM48_MT_CC_ALERTING (0x3:0x1)
627DMNCC transmit message MNCC_ALERT_IND
628 MSC --> MNCC: callref 0x423: MNCC_ALERT_IND
629DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
630DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
631DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC
632DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
633- Total time passed: 2.000046 s
634 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_CONNECT
635DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
636DRLL Dispatching 04.08 message GSM48_MT_CC_CONNECT (0x3:0x7)
637DMNCC transmit message MNCC_SETUP_CNF
638 MSC --> MNCC: callref 0x423: MNCC_SETUP_CNF
639DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
640DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
641DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC
642DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
643DMNCC receive message MNCC_SETUP_COMPL_REQ
644DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
645- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CONNECT_ACK: 030f
646- DTAP matches expected message
647---
648- RTP stream goes ahead, not shown here.
649- Total time passed: 125.000091 s
650---
651- Call ends
652 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_DISCONNECT
653DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
654DRLL Dispatching 04.08 message GSM48_MT_CC_DISCONNECT (0x3:0x25)
655DMNCC transmit message MNCC_DISC_IND
656 MSC --> MNCC: callref 0x423: MNCC_DISC_IND
657DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
658DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
659DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: connection still has active transaction: GSM48_PDISC_CC
660DREF MSISDN:42342: MSC conn use - dtap == 1 (0x4)
661DMNCC receive message MNCC_REL_REQ
662DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
663- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 032d
664- DTAP matches expected message
665 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_RELEASE_COMPL
666DREF MSISDN:42342: MSC conn use + dtap == 2 (0x6)
667DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a)
668DMNCC transmit message MNCC_REL_CNF
669 MSC --> MNCC: callref 0x423: MNCC_REL_CNF
670 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x0
671DREF VLR subscr MSISDN:42342 usage decreases to: 2
672DREF MSISDN:42342: MSC conn use error: freeing an unused token: trans_cc
673DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x6)
674DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
675DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_BUMP
676DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: bump: releasing conn
677DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASED
678DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
679DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
680DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(901700000010650)
681DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Freeing instance
682DVLR Process_Access_Request_VLR(901700000010650){PR_ARQ_S_DONE}: Deallocated
683DMM msc_subscr_conn_close(vsub=MSISDN:42342, cause=2): no conn fsm, releasing directly without release event.
684- Iu Release --RAN_UTRAN_IU--> MS
685DREF MSISDN:42342: MSC conn use - fsm == 0 (0x2)
686DRLL subscr MSISDN:42342: Freeing subscriber connection
687DREF VLR subscr MSISDN:42342 usage decreases to: 1
688DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
689DMM Subscr_Conn(901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
690DREF unknown: MSC conn use - dtap failed: is already 0
691 llist_count(&net->subscr_conns) == 0
692DREF freeing VLR subscr MSISDN:42342
693===== test_call_mt: SUCCESS
694
695full talloc report on 'msgb' (total 0 bytes in 1 blocks)
696talloc_total_blocks(tall_bsc_ctx) == 9
697
698full talloc report on 'msgb' (total 0 bytes in 1 blocks)
699talloc_total_blocks(tall_bsc_ctx) == 9
700