blob: 936f61cd33135376d36a99a6c4a14f0c946061fd [file] [log] [blame]
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001full 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 +01004===== test_call_mo
Neels Hofmeyra99b4272017-11-21 17:13:23 +01005- 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
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02009DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +020010DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +010011DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020012DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyra99b4272017-11-21 17:13:23 +010013DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
14DMM LU/new-LAC: 23/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020015DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Allocated
16DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000010650)
17DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
18DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyra99b4272017-11-21 17:13:23 +010019DREF VLR subscr unknown usage increases to: 1
20DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
21DVLR New subscr, IMSI: 901700000010650
22DREF VLR subscr IMSI:901700000010650 usage increases to: 2
23DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020024DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
25DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
26DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
27DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650)
28DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyra99b4272017-11-21 17:13:23 +010029DVLR GSUP tx: 08010809710000000156f0
30GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020031DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
32DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
33DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +020034DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020035DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
36DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyra99b4272017-11-21 17:13:23 +010037 lu_result_sent == 0
38- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
39<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
40DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
41DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020042DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyra99b4272017-11-21 17:13:23 +010043DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020044DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
45DVLR VLR_Authenticate(LU: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 +010046- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
47- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
48- ...autn=8704f5ba55f30000d2ee44b22c8ea919
49- ...expecting res=e229c19e791f2e41
50DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
51<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
52 auth_request_sent == 1
53 lu_result_sent == 0
54- MS sends Authen Response, VLR accepts and sends SecurityModeControl
55 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +020056DREF IMSI:901700000010650: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +010057DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +010058DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020059DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +010060DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +010061DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +020062DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020063DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
64DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
65DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650)
66DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
67DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
68DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
69DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
70DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +010071DMM -> SECURITY MODE CONTROL IMSI:901700000010650
72- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
73- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020074DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +020075DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020076DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
77DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +010078 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-11-21 17:13:23 +010079 lu_result_sent == 0
80- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
81DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020082DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
83DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
Neels Hofmeyra99b4272017-11-21 17:13:23 +010084DIUCS IMSI:901700000010650: tx CommonID 901700000010650
85- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020086DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
87DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
88DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
89DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
90DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +020091DVLR GSUP tx: 04010809710000000156f0280102
92GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +020093DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyra99b4272017-11-21 17:13:23 +010094 gsup_tx_confirmed == 1
95 lu_result_sent == 0
96- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
97<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
98DVLR GSUP rx 17: 10010809710000000156f00804032443f2
99DREF VLR subscr IMSI:901700000010650 usage increases to: 2
100DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +0100101DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100102DVLR GSUP tx: 12010809710000000156f0
103GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
104DREF VLR subscr MSISDN:42342 usage decreases to: 1
105<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
106 lu_result_sent == 0
107- HLR also sends GSUP _UPDATE_LOCATION_RESULT
108<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
109DVLR GSUP rx 11: 06010809710000000156f0
110DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200111DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
112DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
113DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
114DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
115DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
116DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
117DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
118DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
119DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
120DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
121DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
122DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
123DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
124DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
125DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000010650)
126DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
127DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
128DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
129DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000010650)
130DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
131DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
132DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
133DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
134DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100135- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
136DREF VLR subscr MSISDN:42342 usage decreases to: 1
137<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
138 lu_result_sent == 1
139- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
140 llist_count(&net->subscr_conns) == 1
141msc_subscr_conn_is_accepted() == false
142- MS sends TMSI Realloc Complete
143 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200144DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100145DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
146DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200147DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
148DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100149DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200150DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
151DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
152DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
153DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
154DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
155DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
156DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
157DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
158DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
159DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
160DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200161DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200162DREF VLR subscr MSISDN:42342 usage increases to: 3
163DREF VLR subscr MSISDN:42342 usage decreases to: 2
164- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200165DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200166 iu_release_sent == 1
167- LU was successful, and the conn has already been closed
168- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200169DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200170DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
171DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
172DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
173DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
174DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000010650)
175DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
176DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Freeing instance
177DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200178DRLL MSISDN:42342: Freeing subscriber connection
179DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200180DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
181DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100182 llist_count(&net->subscr_conns) == 0
183DREF VLR subscr MSISDN:42342 usage increases to: 2
184 vsub != NULL == 1
185 strcmp(vsub->imsi, IMSI) == 0
186 vsub->lac == 23
187DREF VLR subscr MSISDN:42342 usage decreases to: 1
188---
189- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
190 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_CM_SERV_REQ
191 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200192DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200193DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100194DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
195DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200196DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Updated ID
197DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Allocated
198DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(CM_SERVICE_REQ:901700000010650)
199DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
200DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100201DREF VLR subscr MSISDN:42342 usage increases to: 2
202DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200203DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
204DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
205DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
206DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
207DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
208DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
209DVLR VLR_Authenticate(CM_SERVICE_REQ: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 +0100210- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
211- ...rand=c187a53a5e6b9d573cac7c74451fd46d
212- ...autn=1843a645b98d00005b2d666af46c45d9
213- ...expecting res=7db47cf7f81e4dc7
214DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200215DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
216DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200217DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200218DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
219DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100220 cm_service_result_sent == 0
221 auth_request_sent == 1
222- needs auth, not yet accepted
223msc_subscr_conn_is_accepted() == false
224- MS sends Authen Response, VLR accepts and sends SecurityModeControl
225 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200226DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100227DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100228DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200229DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100230DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100231DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200232DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200233DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
234DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
235DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
236DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
237DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
238DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200239DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
240DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100241DMM -> SECURITY MODE CONTROL MSISDN:42342
242- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
243- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200244DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200245DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200246DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
247DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100248 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100249 cm_service_result_sent == 0
250- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
251DMM <- SECURITY MODE COMPLETE MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200252DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
253DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100254DIUCS MSISDN:42342: tx CommonID 901700000010650
255- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200256DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
257DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
258DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
259DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200260DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200261DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200262DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200263DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200264DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200265DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
266DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100267 cm_service_result_sent == 0
268---
269- a call is initiated
270- SETUP gets forwarded to MNCC
271 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_SETUP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200272DREF MSISDN:42342: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100273DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100274DCC Unknown transaction ID 8, creating new trans.
275DCC (ti 08 sub MSISDN:42342 callref 80000001) New transaction
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100276DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200277DREF MSISDN:42342: MSC conn use + trans_cc == 3 (0x1a: dtap,cm_service,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100278DMM MSISDN:42342: rx msg GSM48_MT_CC_SETUP: received_cm_service_request changes to false
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200279DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x12: dtap,trans_cc)
Philipp Maier9ca7b312018-10-10 17:00:49 +0200280DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100281DCC (ti 08 sub MSISDN:42342) new state NULL -> INITIATED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100282DCC Subscriber MSISDN:42342 (42342) sends SETUP to 123
283DMNCC transmit message MNCC_SETUP_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100284DCC Sending 'MNCC_SETUP_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100285 MSC --> MNCC: callref 0x80000001: MNCC_SETUP_IND
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200286DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
287DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200288DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100289- MNCC says that's fine
290DMNCC receive message MNCC_CALL_PROC_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200291DCC (sub 42342) stopping pending guard timer
292DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100293DCC (ti 08 sub 42342) Received 'MNCC_CALL_PROC_REQ' from MNCC in state 1 (INITIATED)
294DCC (ti 08 sub MSISDN:42342) new state INITIATED -> MO_CALL_PROC
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100295DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
296- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CALL_PROC: 8302
297- DTAP matches expected message
298 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x80000001
299- Total time passed: 1.000023 s
300- The other call leg got established (not shown here), MNCC tells us so
301DMNCC receive message MNCC_ALERT_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200302DCC (sub 42342) stopping pending guard timer
303DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100304DCC (ti 08 sub 42342) Received 'MNCC_ALERT_REQ' from MNCC in state 3 (MO_CALL_PROC)
305DCC (ti 08 sub MSISDN:42342) new state MO_CALL_PROC -> CALL_DELIVERED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100306DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
307- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_ALERTING: 8301
308- DTAP matches expected message
309DMNCC receive message MNCC_SETUP_RSP
Philipp Maier9ca7b312018-10-10 17:00:49 +0200310DCC (sub 42342) stopping pending guard timer
311DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100312DCC (ti 08 sub 42342) Received 'MNCC_SETUP_RSP' from MNCC in state 4 (CALL_DELIVERED)
313DCC starting timer T313 with 30 seconds
314DCC (ti 08 sub MSISDN:42342) new state CALL_DELIVERED -> CONNECT_IND
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100315DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
316- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CONNECT: 8307
317- DTAP matches expected message
318- Total time passed: 2.000046 s
319 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_CONNECT_ACK
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200320DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100321DRLL Dispatching 04.08 message GSM48_MT_CC_CONNECT_ACK (0x3:0xf)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100322DCC stopping pending timer T313
323DCC (ti 08 sub MSISDN:42342) new state CONNECT_IND -> ACTIVE
Philipp Maier9ca7b312018-10-10 17:00:49 +0200324DCC (sub 42342) stopping pending guard timer
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100325DMNCC transmit message MNCC_SETUP_COMPL_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100326DCC Sending 'MNCC_SETUP_COMPL_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100327 MSC --> MNCC: callref 0x80000001: MNCC_SETUP_COMPL_IND
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200328DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200329DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100330---
331- RTP stream goes ahead, not shown here.
332- Total time passed: 125.000091 s
333---
334- Call ends
335 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_DISCONNECT
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200336DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100337DRLL Dispatching 04.08 message GSM48_MT_CC_DISCONNECT (0x3:0x25)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100338DCC (ti 08 sub MSISDN:42342) new state ACTIVE -> DISCONNECT_IND
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100339DMNCC transmit message MNCC_DISC_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100340DCC Sending 'MNCC_DISC_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100341 MSC --> MNCC: callref 0x80000001: MNCC_DISC_IND
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200342DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200343DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100344DMNCC receive message MNCC_REL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200345DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100346DCC (ti 08 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 12 (DISCONNECT_IND)
347DCC starting timer T308 with 10 seconds
348DCC (ti 08 sub MSISDN:42342) new state DISCONNECT_IND -> RELEASE_REQ
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100349DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
350- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d
351- DTAP matches expected message
352 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_RELEASE_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200353DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100354DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100355DCC stopping pending timer T308
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100356DMNCC transmit message MNCC_REL_CNF
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100357DCC Sending 'MNCC_REL_CNF' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100358 MSC --> MNCC: callref 0x80000001: MNCC_REL_CNF
359 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x0
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100360DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Philipp Maier9ca7b312018-10-10 17:00:49 +0200361DCC (sub 42342) stopping pending guard timer
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100362DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200363DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x2: dtap)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200364DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200365DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200366DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
367DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200368DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200369DREF VLR subscr MSISDN:42342 usage increases to: 3
370DREF VLR subscr MSISDN:42342 usage decreases to: 2
371- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200372- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200373DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200374DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
375DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
376DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
377DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
378DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650)
379DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Freeing instance
380DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200381DRLL MSISDN:42342: Freeing subscriber connection
382DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200383DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
384DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100385 llist_count(&net->subscr_conns) == 0
386DREF freeing VLR subscr MSISDN:42342
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100387===== test_call_mo: SUCCESS
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100388
389full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200390talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100391
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100392===== test_call_mt
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100393- Total time passed: 0.000000 s
394- Location Update request causes a GSUP Send Auth Info request to HLR
395 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
396 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200397DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200398DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100399DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200400DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100401DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
402DMM LU/new-LAC: 23/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200403DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Allocated
404DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000010650)
405DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
406DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100407DREF VLR subscr unknown usage increases to: 1
408DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
409DVLR New subscr, IMSI: 901700000010650
410DREF VLR subscr IMSI:901700000010650 usage increases to: 2
411DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200412DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
413DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
414DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
415DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650)
416DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100417DVLR GSUP tx: 08010809710000000156f0
418GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200419DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
420DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
421DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200422DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200423DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
424DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100425 lu_result_sent == 0
426- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
427<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
428DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
429DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200430DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100431DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200432DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
433DVLR VLR_Authenticate(LU: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 +0100434- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
435- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
436- ...autn=8704f5ba55f30000d2ee44b22c8ea919
437- ...expecting res=e229c19e791f2e41
438DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
439<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
440 auth_request_sent == 1
441 lu_result_sent == 0
442- MS sends Authen Response, VLR accepts and sends SecurityModeControl
443 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200444DREF IMSI:901700000010650: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100445DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100446DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200447DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100448DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100449DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200450DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200451DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
452DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
453DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650)
454DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
455DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
456DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
457DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
458DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100459DMM -> SECURITY MODE CONTROL IMSI:901700000010650
460- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
461- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200462DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200463DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200464DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
465DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100466 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100467 lu_result_sent == 0
468- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
469DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200470DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
471DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100472DIUCS IMSI:901700000010650: tx CommonID 901700000010650
473- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200474DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
475DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
476DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
477DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
478DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +0200479DVLR GSUP tx: 04010809710000000156f0280102
480GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200481DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100482 gsup_tx_confirmed == 1
483 lu_result_sent == 0
484- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
485<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
486DVLR GSUP rx 17: 10010809710000000156f00804032443f2
487DREF VLR subscr IMSI:901700000010650 usage increases to: 2
488DVLR IMSI:901700000010650 has MSISDN:42342
Maxa263bb22017-12-27 13:23:44 +0100489DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100490DVLR GSUP tx: 12010809710000000156f0
491GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
492DREF VLR subscr MSISDN:42342 usage decreases to: 1
493<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
494 lu_result_sent == 0
495- HLR also sends GSUP _UPDATE_LOCATION_RESULT
496<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
497DVLR GSUP rx 11: 06010809710000000156f0
498DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200499DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
500DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
501DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
502DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
503DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
504DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
505DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
506DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
507DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
508DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
509DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
510DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
511DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
512DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
513DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000010650)
514DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
515DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
516DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
517DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000010650)
518DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
519DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
520DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
521DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
522DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100523- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
524DREF VLR subscr MSISDN:42342 usage decreases to: 1
525<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
526 lu_result_sent == 1
527- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
528 llist_count(&net->subscr_conns) == 1
529msc_subscr_conn_is_accepted() == false
530- MS sends TMSI Realloc Complete
531 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200532DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100533DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
534DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200535DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
536DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100537DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200538DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
539DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
540DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
541DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
542DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
543DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
544DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
545DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
546DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
547DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
548DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200549DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200550DREF VLR subscr MSISDN:42342 usage increases to: 3
551DREF VLR subscr MSISDN:42342 usage decreases to: 2
552- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200553DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200554 iu_release_sent == 1
555- LU was successful, and the conn has already been closed
556- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200557DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200558DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
559DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
560DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
561DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
562DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000010650)
563DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
564DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Freeing instance
565DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200566DRLL MSISDN:42342: Freeing subscriber connection
567DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200568DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
569DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100570 llist_count(&net->subscr_conns) == 0
571DREF VLR subscr MSISDN:42342 usage increases to: 2
572 vsub != NULL == 1
573 strcmp(vsub->imsi, IMSI) == 0
574 vsub->lac == 23
575DREF VLR subscr MSISDN:42342 usage decreases to: 1
576---
577- after a while, MNCC asks us to setup a call, causing Paging
578DMNCC receive message MNCC_SETUP_REQ
579DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100580DCC (ti ff sub MSISDN:42342 callref 423) New transaction
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100581DREF VLR subscr MSISDN:42342 usage increases to: 3
582DMM Subscriber MSISDN:42342 not paged yet, start paging.
583 RAN_UTRAN_IU sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23
584 strcmp(paging_expecting_imsi, imsi) == 0
585DREF VLR subscr MSISDN:42342 usage increases to: 4
586DREF VLR subscr MSISDN:42342 usage decreases to: 3
587 paging_sent == 1
588 paging_stopped == 0
589- MS replies with Paging Response, and VLR sends Auth Request
590 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_RR_PAG_RESP
591 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200592DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200593DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100594DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
595DRR PAGING RESPONSE: MI(IMSI)=901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200596DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: Updated ID
597DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Allocated
598DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000010650)
599DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
600DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100601DREF VLR subscr MSISDN:42342 usage increases to: 4
602DREF VLR subscr MSISDN:42342 usage increases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200603DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
604DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
605DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
606DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(PAGING_RESP:901700000010650)
607DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
608DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
609DVLR VLR_Authenticate(PAGING_RESP: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 +0100610- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
611- ...rand=c187a53a5e6b9d573cac7c74451fd46d
612- ...autn=1843a645b98d00005b2d666af46c45d9
613- ...expecting res=7db47cf7f81e4dc7
614DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200615DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
616DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200617DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200618DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
619DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100620 auth_request_sent == 1
621- MS sends Authen Response, VLR accepts and sends SecurityModeControl
622 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200623DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100624DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
Neels Hofmeyrd97821f2018-03-10 04:51:39 +0100625DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200626DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyra9099bc2018-03-10 04:22:50 +0100627DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100628DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200629DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200630DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
631DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
632DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(PAGING_RESP:901700000010650)
633DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
634DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
635DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200636DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
637DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrda21a522018-03-02 01:50:09 +0100638DMM -> SECURITY MODE CONTROL MSISDN:42342
639- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
640- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200641DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200642DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200643DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
644DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyrdbabfd32018-03-10 02:06:47 +0100645 security_mode_ctrl_sent == 1
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100646- MS sends SecurityModeControl acceptance, VLR accepts, sends CC Setup
647DMM <- SECURITY MODE COMPLETE MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200648DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
649DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100650DIUCS MSISDN:42342: tx CommonID 901700000010650
651- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200652DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
653DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
654DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
655DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +0200656DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200657DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +0200658DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200659DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100660DPAG Paging success for MSISDN:42342 (event=0)
661DPAG Calling paging cbfn.
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100662DCC Paging subscr 42342 succeeded!
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200663DREF MSISDN:42342: MSC conn use + trans_cc == 1 (0x10: trans_cc)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100664DCC starting timer T303 with 30 seconds
665DCC (ti 00 sub MSISDN:42342) new state NULL -> CALL_PRESENT
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100666DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
667- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_SETUP: 0305
668- DTAP matches expected message
669DREF VLR subscr MSISDN:42342 usage decreases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200670DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
671DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: CC
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100672 paging_stopped == 1
673 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_CALL_CONF
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200674DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100675DRLL Dispatching 04.08 message GSM48_MT_CC_CALL_CONF (0x3:0x8)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100676DCC stopping pending timer T303
677DCC starting timer T310 with 30 seconds
678DCC (ti 00 sub MSISDN:42342) new state CALL_PRESENT -> MO_TERM_CALL_CONF
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100679 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x423
680DMNCC transmit message MNCC_CALL_CONF_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100681DCC Sending 'MNCC_CALL_CONF_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100682 MSC --> MNCC: callref 0x423: MNCC_CALL_CONF_IND
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200683DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
684DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200685DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100686- Total time passed: 1.000023 s
687 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_ALERTING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200688DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100689DRLL Dispatching 04.08 message GSM48_MT_CC_ALERTING (0x3:0x1)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100690DCC stopping pending timer T310
691DCC starting timer T301 with 180 seconds
692DCC (ti 00 sub MSISDN:42342) new state MO_TERM_CALL_CONF -> CALL_RECEIVED
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100693DMNCC transmit message MNCC_ALERT_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100694DCC Sending 'MNCC_ALERT_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100695 MSC --> MNCC: callref 0x423: MNCC_ALERT_IND
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200696DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200697DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100698- Total time passed: 2.000046 s
699 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_CONNECT
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200700DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100701DRLL Dispatching 04.08 message GSM48_MT_CC_CONNECT (0x3:0x7)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100702DCC stopping pending timer T301
703DCC (ti 00 sub MSISDN:42342) new state CALL_RECEIVED -> CONNECT_REQUEST
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100704DMNCC transmit message MNCC_SETUP_CNF
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100705DCC Sending 'MNCC_SETUP_CNF' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100706 MSC --> MNCC: callref 0x423: MNCC_SETUP_CNF
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200707DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200708DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100709DMNCC receive message MNCC_SETUP_COMPL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200710DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100711DCC (ti 00 sub 42342) Received 'MNCC_SETUP_COMPL_REQ' from MNCC in state 8 (CONNECT_REQUEST)
712DCC (ti 00 sub MSISDN:42342) new state CONNECT_REQUEST -> ACTIVE
Philipp Maier9ca7b312018-10-10 17:00:49 +0200713DCC (sub 42342) stopping pending guard timer
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100714DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
715- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CONNECT_ACK: 030f
716- DTAP matches expected message
717---
718- RTP stream goes ahead, not shown here.
719- Total time passed: 125.000091 s
720---
721- Call ends
722 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_DISCONNECT
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200723DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100724DRLL Dispatching 04.08 message GSM48_MT_CC_DISCONNECT (0x3:0x25)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100725DCC (ti 00 sub MSISDN:42342) new state ACTIVE -> DISCONNECT_IND
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100726DMNCC transmit message MNCC_DISC_IND
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100727DCC Sending 'MNCC_DISC_IND' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100728 MSC --> MNCC: callref 0x423: MNCC_DISC_IND
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200729DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200730DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100731DMNCC receive message MNCC_REL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +0200732DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100733DCC (ti 00 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 12 (DISCONNECT_IND)
734DCC starting timer T308 with 10 seconds
735DCC (ti 00 sub MSISDN:42342) new state DISCONNECT_IND -> RELEASE_REQ
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100736DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
737- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 032d
738- DTAP matches expected message
739 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_RELEASE_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200740DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100741DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a)
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100742DCC stopping pending timer T308
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100743DMNCC transmit message MNCC_REL_CNF
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100744DCC Sending 'MNCC_REL_CNF' to MNCC.
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100745 MSC --> MNCC: callref 0x423: MNCC_REL_CNF
746 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x0
Neels Hofmeyr12e17be2018-03-12 23:59:37 +0100747DCC (ti 00 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Philipp Maier9ca7b312018-10-10 17:00:49 +0200748DCC (sub 42342) stopping pending guard timer
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100749DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200750DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x2: dtap)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200751DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200752DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200753DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
754DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200755DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200756DREF VLR subscr MSISDN:42342 usage increases to: 3
757DREF VLR subscr MSISDN:42342 usage decreases to: 2
758- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200759- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200760DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200761DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
762DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
763DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
764DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
765DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(PAGING_RESP:901700000010650)
766DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Freeing instance
767DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200768DRLL MSISDN:42342: Freeing subscriber connection
769DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200770DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
771DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100772 llist_count(&net->subscr_conns) == 0
773DREF freeing VLR subscr MSISDN:42342
Neels Hofmeyrdfdc61d2018-03-02 00:40:58 +0100774===== test_call_mt: SUCCESS
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100775
776full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +0200777talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyra99b4272017-11-21 17:13:23 +0100778
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100779===== test_call_mt2
780- Total time passed: 0.000000 s
781- Location Update request causes a GSUP Send Auth Info request to HLR
782 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
783 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200784DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200785DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100786DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200787DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100788DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
789DMM LU/new-LAC: 23/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200790DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Allocated
791DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000010650)
792DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
793DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100794DREF VLR subscr unknown usage increases to: 1
795DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
796DVLR New subscr, IMSI: 901700000010650
797DREF VLR subscr IMSI:901700000010650 usage increases to: 2
798DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200799DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
800DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
801DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
802DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650)
803DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100804DVLR GSUP tx: 08010809710000000156f0
805GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200806DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
807DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
808DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200809DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200810DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
811DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100812 lu_result_sent == 0
813- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
814<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
815DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
816DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200817DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100818DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200819DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
820DVLR VLR_Authenticate(LU: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 Hofmeyrcbcf89c2018-03-13 17:52:07 +0100821- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
822- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
823- ...autn=8704f5ba55f30000d2ee44b22c8ea919
824- ...expecting res=e229c19e791f2e41
825DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
826<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
827 auth_request_sent == 1
828 lu_result_sent == 0
829- MS sends Authen Response, VLR accepts and sends SecurityModeControl
830 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200831DREF IMSI:901700000010650: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100832DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
833DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200834DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100835DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
836DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +0200837DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200838DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
839DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
840DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650)
841DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
842DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
843DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
844DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
845DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100846DMM -> SECURITY MODE CONTROL IMSI:901700000010650
847- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
848- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200849DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200850DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200851DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
852DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100853 security_mode_ctrl_sent == 1
854 lu_result_sent == 0
855- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
856DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200857DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
858DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100859DIUCS IMSI:901700000010650: tx CommonID 901700000010650
860- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200861DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
862DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
863DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
864DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
865DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +0200866DVLR GSUP tx: 04010809710000000156f0280102
867GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200868DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100869 gsup_tx_confirmed == 1
870 lu_result_sent == 0
871- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
872<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
873DVLR GSUP rx 17: 10010809710000000156f00804032443f2
874DREF VLR subscr IMSI:901700000010650 usage increases to: 2
875DVLR IMSI:901700000010650 has MSISDN:42342
876DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
877DVLR GSUP tx: 12010809710000000156f0
878GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
879DREF VLR subscr MSISDN:42342 usage decreases to: 1
880<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
881 lu_result_sent == 0
882- HLR also sends GSUP _UPDATE_LOCATION_RESULT
883<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
884DVLR GSUP rx 11: 06010809710000000156f0
885DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200886DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
887DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
888DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
889DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
890DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
891DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
892DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
893DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
894DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
895DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
896DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
897DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
898DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
899DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
900DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000010650)
901DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
902DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
903DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
904DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000010650)
905DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
906DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
907DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
908DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
909DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100910- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
911DREF VLR subscr MSISDN:42342 usage decreases to: 1
912<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
913 lu_result_sent == 1
914- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
915 llist_count(&net->subscr_conns) == 1
916msc_subscr_conn_is_accepted() == false
917- MS sends TMSI Realloc Complete
918 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200919DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100920DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
921DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200922DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
923DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100924DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200925DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
926DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
927DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
928DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
929DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
930DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
931DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
932DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
933DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
934DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
935DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200936DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200937DREF VLR subscr MSISDN:42342 usage increases to: 3
938DREF VLR subscr MSISDN:42342 usage decreases to: 2
939- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200940DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +0200941 iu_release_sent == 1
942- LU was successful, and the conn has already been closed
943- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200944DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200945DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
946DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
947DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
948DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
949DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000010650)
950DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
951DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Freeing instance
952DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200953DRLL MSISDN:42342: Freeing subscriber connection
954DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200955DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
956DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100957 llist_count(&net->subscr_conns) == 0
958DREF VLR subscr MSISDN:42342 usage increases to: 2
959 vsub != NULL == 1
960 strcmp(vsub->imsi, IMSI) == 0
961 vsub->lac == 23
962DREF VLR subscr MSISDN:42342 usage decreases to: 1
963---
964- after a while, MNCC asks us to setup a call, causing Paging
965DMNCC receive message MNCC_SETUP_REQ
966DREF VLR subscr MSISDN:42342 usage increases to: 2
967DCC (ti ff sub MSISDN:42342 callref 423) New transaction
968DREF VLR subscr MSISDN:42342 usage increases to: 3
969DMM Subscriber MSISDN:42342 not paged yet, start paging.
970 RAN_UTRAN_IU sends out paging request to IMSI 901700000010650, TMSI 0x03020100, LAC 23
971 strcmp(paging_expecting_imsi, imsi) == 0
972DREF VLR subscr MSISDN:42342 usage increases to: 4
973DREF VLR subscr MSISDN:42342 usage decreases to: 3
974 paging_sent == 1
975 paging_stopped == 0
976- MS replies with Paging Response, and VLR sends Auth Request
977 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_RR_PAG_RESP
978 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +0200979DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +0200980DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100981DRLL Dispatching 04.08 message GSM48_MT_RR_PAG_RESP (0x6:0x27)
982DRR PAGING RESPONSE: MI(IMSI)=901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200983DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: Updated ID
984DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Allocated
985DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(PAGING_RESP:901700000010650)
986DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
987DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +0100988DREF VLR subscr MSISDN:42342 usage increases to: 4
989DREF VLR subscr MSISDN:42342 usage increases to: 5
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +0200990DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
991DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
992DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
993DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(PAGING_RESP:901700000010650)
994DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
995DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
996DVLR VLR_Authenticate(PAGING_RESP: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 Hofmeyrcbcf89c2018-03-13 17:52:07 +0100997- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
998- ...rand=c187a53a5e6b9d573cac7c74451fd46d
999- ...autn=1843a645b98d00005b2d666af46c45d9
1000- ...expecting res=7db47cf7f81e4dc7
1001DREF VLR subscr MSISDN:42342 usage decreases to: 4
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001002DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1003DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001004DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001005DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1006DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001007 auth_request_sent == 1
1008- MS sends Authen Response, VLR accepts and sends SecurityModeControl
1009 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001010DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001011DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1012DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001013DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001014DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
1015DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +02001016DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001017DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1018DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1019DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(PAGING_RESP:901700000010650)
1020DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1021DVLR VLR_Authenticate(PAGING_RESP:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1022DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001023DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1024DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001025DMM -> SECURITY MODE CONTROL MSISDN:42342
1026- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1027- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001028DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001029DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001030DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1031DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001032 security_mode_ctrl_sent == 1
1033- MS sends SecurityModeControl acceptance, VLR accepts, sends CC Setup
1034DMM <- SECURITY MODE COMPLETE MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001035DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
1036DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001037DIUCS MSISDN:42342: tx CommonID 901700000010650
1038- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001039DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
1040DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
1041DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
1042DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +02001043DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001044DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +02001045DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001046DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001047DPAG Paging success for MSISDN:42342 (event=0)
1048DPAG Calling paging cbfn.
1049DCC Paging subscr 42342 succeeded!
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001050DREF MSISDN:42342: MSC conn use + trans_cc == 1 (0x10: trans_cc)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001051DCC starting timer T303 with 30 seconds
1052DCC (ti 00 sub MSISDN:42342) new state NULL -> CALL_PRESENT
1053DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1054- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_SETUP: 0305
1055- DTAP matches expected message
1056DREF VLR subscr MSISDN:42342 usage decreases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001057DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1058DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: connection still has active transaction: CC
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001059 paging_stopped == 1
1060 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_CALL_CONF
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001061DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001062DRLL Dispatching 04.08 message GSM48_MT_CC_CALL_CONF (0x3:0x8)
1063DCC stopping pending timer T303
1064DCC starting timer T310 with 30 seconds
1065DCC (ti 00 sub MSISDN:42342) new state CALL_PRESENT -> MO_TERM_CALL_CONF
1066 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x423
1067DMNCC transmit message MNCC_CALL_CONF_IND
1068DCC Sending 'MNCC_CALL_CONF_IND' to MNCC.
1069 MSC --> MNCC: callref 0x423: MNCC_CALL_CONF_IND
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001070DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1071DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001072DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001073- Total time passed: 1.000023 s
1074 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_ALERTING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001075DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001076DRLL Dispatching 04.08 message GSM48_MT_CC_ALERTING (0x3:0x1)
1077DCC stopping pending timer T310
1078DCC starting timer T301 with 180 seconds
1079DCC (ti 00 sub MSISDN:42342) new state MO_TERM_CALL_CONF -> CALL_RECEIVED
1080DMNCC transmit message MNCC_ALERT_IND
1081DCC Sending 'MNCC_ALERT_IND' to MNCC.
1082 MSC --> MNCC: callref 0x423: MNCC_ALERT_IND
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001083DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001084DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001085- Total time passed: 16.000046 s
1086- The call failed, the BSC sends a BSSMAP Clear Request
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001087DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_CN_CLOSE
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001088DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001089DREF MSISDN:42342: MSC conn use + release == 2 (0x110: trans_cc,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001090DREF VLR subscr MSISDN:42342 usage increases to: 4
1091DREF VLR subscr MSISDN:42342 usage decreases to: 3
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001092DCC stopping pending timer T301
1093 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x423
1094DMNCC receive message MNCC_REL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +02001095DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001096DCC (ti 00 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 7 (CALL_RECEIVED)
1097DCC starting timer T308 with 10 seconds
1098DCC (ti 00 sub MSISDN:42342) new state CALL_RECEIVED -> RELEASE_REQ
1099DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1100- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 032d
1101- DTAP matches expected message
1102DMNCC transmit message MNCC_REL_CNF
1103DCC Sending 'MNCC_REL_CNF' to MNCC.
1104 MSC --> MNCC: callref 0x423: MNCC_REL_CNF
Neels Hofmeyrdc2514b2018-04-09 23:29:14 +02001105DCC stopping pending timer T308
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001106DCC (ti 00 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Philipp Maier9ca7b312018-10-10 17:00:49 +02001107DCC (sub 42342) stopping pending guard timer
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001108DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001109DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x100: release)
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001110- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001111- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001112DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001113DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1114DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1115DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1116DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1117DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(PAGING_RESP:901700000010650)
1118DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Freeing instance
1119DVLR Process_Access_Request_VLR(PAGING_RESP:901700000010650){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001120DRLL MSISDN:42342: Freeing subscriber connection
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001121DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001122DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1123DMM Subscr_Conn(PAGING_RESP:901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyrcbcf89c2018-03-13 17:52:07 +01001124 llist_count(&net->subscr_conns) == 0
1125- Total time passed: 31.000069 s
1126DREF freeing VLR subscr MSISDN:42342
1127===== test_call_mt2: SUCCESS
1128
1129full talloc report on 'msgb' (total 0 bytes in 1 blocks)
1130talloc_total_blocks(tall_bsc_ctx) == 12
1131
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001132===== test_call_mo_to_unknown
1133- Total time passed: 0.000000 s
1134- Location Update request causes a GSUP Send Auth Info request to HLR
1135 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1136 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001137DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001138DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001139DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001140DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001141DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1142DMM LU/new-LAC: 23/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001143DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Allocated
1144DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000010650)
1145DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
1146DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001147DREF VLR subscr unknown usage increases to: 1
1148DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1149DVLR New subscr, IMSI: 901700000010650
1150DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1151DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001152DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1153DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1154DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1155DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650)
1156DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001157DVLR GSUP tx: 08010809710000000156f0
1158GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001159DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
1160DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1161DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001162DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001163DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1164DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001165 lu_result_sent == 0
1166- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1167<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1168DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1169DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001170DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001171DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001172DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
1173DVLR VLR_Authenticate(LU: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 Hofmeyreb1cfdb2018-03-15 13:42:10 +01001174- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1175- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1176- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1177- ...expecting res=e229c19e791f2e41
1178DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1179<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1180 auth_request_sent == 1
1181 lu_result_sent == 0
1182- MS sends Authen Response, VLR accepts and sends SecurityModeControl
1183 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001184DREF IMSI:901700000010650: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001185DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1186DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001187DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001188DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
1189DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +02001190DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001191DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1192DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1193DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1194DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1195DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1196DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1197DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1198DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001199DMM -> SECURITY MODE CONTROL IMSI:901700000010650
1200- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1201- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001202DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001203DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001204DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1205DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001206 security_mode_ctrl_sent == 1
1207 lu_result_sent == 0
1208- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
1209DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001210DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1211DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001212DIUCS IMSI:901700000010650: tx CommonID 901700000010650
1213- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001214DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1215DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1216DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1217DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
1218DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +02001219DVLR GSUP tx: 04010809710000000156f0280102
1220GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001221DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001222 gsup_tx_confirmed == 1
1223 lu_result_sent == 0
1224- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1225<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1226DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1227DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1228DVLR IMSI:901700000010650 has MSISDN:42342
1229DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
1230DVLR GSUP tx: 12010809710000000156f0
1231GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1232DREF VLR subscr MSISDN:42342 usage decreases to: 1
1233<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1234 lu_result_sent == 0
1235- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1236<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1237DVLR GSUP rx 11: 06010809710000000156f0
1238DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001239DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1240DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1241DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1242DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1243DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1244DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1245DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1246DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1247DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1248DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1249DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
1250DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1251DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1252DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1253DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000010650)
1254DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1255DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1256DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1257DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000010650)
1258DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1259DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1260DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1261DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1262DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001263- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
1264DREF VLR subscr MSISDN:42342 usage decreases to: 1
1265<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1266 lu_result_sent == 1
1267- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1268 llist_count(&net->subscr_conns) == 1
1269msc_subscr_conn_is_accepted() == false
1270- MS sends TMSI Realloc Complete
1271 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001272DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001273DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
1274DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001275DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1276DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001277DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001278DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1279DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1280DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1281DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1282DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1283DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1284DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1285DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1286DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1287DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1288DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001289DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001290DREF VLR subscr MSISDN:42342 usage increases to: 3
1291DREF VLR subscr MSISDN:42342 usage decreases to: 2
1292- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001293DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001294 iu_release_sent == 1
1295- LU was successful, and the conn has already been closed
1296- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001297DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001298DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1299DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1300DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1301DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1302DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000010650)
1303DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1304DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Freeing instance
1305DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001306DRLL MSISDN:42342: Freeing subscriber connection
1307DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001308DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1309DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001310 llist_count(&net->subscr_conns) == 0
1311DREF VLR subscr MSISDN:42342 usage increases to: 2
1312 vsub != NULL == 1
1313 strcmp(vsub->imsi, IMSI) == 0
1314 vsub->lac == 23
1315DREF VLR subscr MSISDN:42342 usage decreases to: 1
1316---
1317- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
1318 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_CM_SERV_REQ
1319 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001320DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001321DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001322DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
1323DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001324DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Updated ID
1325DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Allocated
1326DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(CM_SERVICE_REQ:901700000010650)
1327DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
1328DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001329DREF VLR subscr MSISDN:42342 usage increases to: 2
1330DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001331DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1332DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1333DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1334DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
1335DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1336DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
1337DVLR VLR_Authenticate(CM_SERVICE_REQ: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 Hofmeyreb1cfdb2018-03-15 13:42:10 +01001338- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
1339- ...rand=c187a53a5e6b9d573cac7c74451fd46d
1340- ...autn=1843a645b98d00005b2d666af46c45d9
1341- ...expecting res=7db47cf7f81e4dc7
1342DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001343DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1344DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001345DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001346DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1347DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001348 cm_service_result_sent == 0
1349 auth_request_sent == 1
1350- needs auth, not yet accepted
1351msc_subscr_conn_is_accepted() == false
1352- MS sends Authen Response, VLR accepts and sends SecurityModeControl
1353 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001354DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001355DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1356DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001357DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001358DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
1359DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +02001360DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001361DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1362DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1363DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
1364DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1365DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1366DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001367DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1368DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001369DMM -> SECURITY MODE CONTROL MSISDN:42342
1370- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1371- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001372DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001373DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001374DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1375DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001376 security_mode_ctrl_sent == 1
1377 cm_service_result_sent == 0
1378- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
1379DMM <- SECURITY MODE COMPLETE MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001380DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
1381DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001382DIUCS MSISDN:42342: tx CommonID 901700000010650
1383- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001384DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
1385DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
1386DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
1387DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +02001388DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001389DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +02001390DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001391DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001392DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001393DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1394DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001395 cm_service_result_sent == 0
1396---
1397- a call is initiated
1398- SETUP gets forwarded to MNCC
1399 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_SETUP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001400DREF MSISDN:42342: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001401DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1402DCC Unknown transaction ID 8, creating new trans.
1403DCC (ti 08 sub MSISDN:42342 callref 80000002) New transaction
1404DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001405DREF MSISDN:42342: MSC conn use + trans_cc == 3 (0x1a: dtap,cm_service,trans_cc)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001406DMM MSISDN:42342: rx msg GSM48_MT_CC_SETUP: received_cm_service_request changes to false
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001407DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x12: dtap,trans_cc)
Philipp Maier9ca7b312018-10-10 17:00:49 +02001408DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001409DCC (ti 08 sub MSISDN:42342) new state NULL -> INITIATED
1410DCC Subscriber MSISDN:42342 (42342) sends SETUP to 123
1411DMNCC transmit message MNCC_SETUP_IND
1412DCC Sending 'MNCC_SETUP_IND' to MNCC.
1413 MSC --> MNCC: callref 0x80000002: MNCC_SETUP_IND
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001414DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1415DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001416DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001417- MNCC says that's fine
1418DMNCC receive message MNCC_CALL_PROC_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +02001419DCC (sub 42342) stopping pending guard timer
1420DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001421DCC (ti 08 sub 42342) Received 'MNCC_CALL_PROC_REQ' from MNCC in state 1 (INITIATED)
1422DCC (ti 08 sub MSISDN:42342) new state INITIATED -> MO_CALL_PROC
1423DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1424- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CALL_PROC: 8302
1425- DTAP matches expected message
1426 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x80000002
1427- But the other side's MSISDN could not be resolved, MNCC tells us to cancel
1428DMNCC receive message MNCC_REL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +02001429DCC (sub 42342) stopping pending guard timer
1430DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001431DCC (ti 08 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 3 (MO_CALL_PROC)
1432DCC starting timer T308 with 10 seconds
1433DCC (ti 08 sub MSISDN:42342) new state MO_CALL_PROC -> RELEASE_REQ
1434DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1435- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d
1436- DTAP matches expected message
1437- Total time passed: 10.000023 s
1438DCC starting timer T308 with 10 seconds
1439DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1440- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d
1441- DTAP matches expected message
1442 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_RELEASE_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001443DREF MSISDN:42342: MSC conn use + dtap == 2 (0x12: dtap,trans_cc)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001444DRLL Dispatching 04.08 message GSM48_MT_CC_RELEASE_COMPL (0x3:0x2a)
1445DCC stopping pending timer T308
1446DMNCC transmit message MNCC_REL_CNF
1447DCC Sending 'MNCC_REL_CNF' to MNCC.
1448 MSC --> MNCC: callref 0x80000002: MNCC_REL_CNF
1449 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x0
1450DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Philipp Maier9ca7b312018-10-10 17:00:49 +02001451DCC (sub 42342) stopping pending guard timer
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001452DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001453DREF MSISDN:42342: MSC conn use - trans_cc == 1 (0x2: dtap)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001454DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001455DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001456DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
1457DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001458DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001459DREF VLR subscr MSISDN:42342 usage increases to: 3
1460DREF VLR subscr MSISDN:42342 usage decreases to: 2
1461- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001462- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001463DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001464DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1465DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1466DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1467DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1468DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650)
1469DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Freeing instance
1470DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001471DRLL MSISDN:42342: Freeing subscriber connection
1472DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001473DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1474DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001475 llist_count(&net->subscr_conns) == 0
1476DREF freeing VLR subscr MSISDN:42342
1477===== test_call_mo_to_unknown: SUCCESS
1478
1479full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001480talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001481
1482===== test_call_mo_to_unknown_timeout
1483- Total time passed: 0.000000 s
1484- Location Update request causes a GSUP Send Auth Info request to HLR
1485 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_LOC_UPD_REQUEST
1486 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001487DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001488DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001489DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001490DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Updated ID
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001491DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000010650 type=NORMAL
1492DMM LU/new-LAC: 23/23
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001493DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Allocated
1494DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000010650)
1495DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: rev=R99 net=UTRAN Auth+Ciph
1496DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001497DREF VLR subscr unknown usage increases to: 1
1498DVLR set IMSI on subscriber; IMSI=901700000010650 id=901700000010650
1499DVLR New subscr, IMSI: 901700000010650
1500DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1501DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001502DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1()
1503DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH
1504DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1505DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650)
1506DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001507DVLR GSUP tx: 08010809710000000156f0
1508GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001509DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI
1510DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1511DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001512DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001513DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1514DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001515 lu_result_sent == 0
1516- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS
1517<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1518DVLR GSUP rx 511: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d21049b36efdf2208059a4f668f6fbe39231027497388b6cb044648f396aa155b95ef2410f64735036e5871319c679f4742a75ea125108704f5ba55f30000d2ee44b22c8ea9192708e229c19e791f2e4103622010c187a53a5e6b9d573cac7c74451fd46d210485aa31302208d3d50a000bf04f6e23101159ec926a50e98c034a6b7d7c9f418d2410df3a03d9ca5335641efc8e36d76cd20b25101843a645b98d00005b2d666af46c45d927087db47cf7f81e4dc703622010efa9c29a9742148d5c9070348716e1bb210469d5f9fb22083df176f0c29f1a3d2310eb50e770ddcc3060101d2f43b6c2b884241076542abce5ff9345b0e8947f4c6e019c2510f9375e6d41e1000096e7fe4ff1c27e392708706f996719ba609c03622010f023d5a3b24726e0631b64b3840f82532104d570c03f2208ec011be8919883d62310c4e58af4ba43f3bcd904e16984f086d724100593f65e752e5cb7f473862bda05aa0a2510541ff1f077270000c5ea00d658bc7e9a27083fd26072eaa2a04d036220102f8f90c780d6a9c0c53da7ac57b6707e2104b072446f220823f39f9f425ad6e6231065af0527fda95b0dc5ae4aa515cdf32f2410537c3b35a3b13b08d08eeb28098f45cc25104bf4e564f75300009bc796706bc6574427080edb0eadbea94ac2
1519DREF VLR subscr IMSI:901700000010650 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001520DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001521DVLR SUBSCR(IMSI:901700000010650) Received 5 auth tuples
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001522DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP
1523DVLR VLR_Authenticate(LU: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 Hofmeyreb1cfdb2018-03-15 13:42:10 +01001524- sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and...
1525- ...rand=39fa2f4e3d523d8619a73b4f65c3e14d
1526- ...autn=8704f5ba55f30000d2ee44b22c8ea919
1527- ...expecting res=e229c19e791f2e41
1528DREF VLR subscr IMSI:901700000010650 usage decreases to: 1
1529<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0
1530 auth_request_sent == 1
1531 lu_result_sent == 0
1532- MS sends Authen Response, VLR accepts and sends SecurityModeControl
1533 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001534DREF IMSI:901700000010650: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001535DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1536DMM IMSI:901700000010650: MM UMTS AUTHENTICATION RESPONSE (res = e229c19e791f2e41)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001537DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001538DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes)
1539DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +02001540DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001541DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1542DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1543DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1544DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1545DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1546DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES
1547DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth()
1548DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001549DMM -> SECURITY MODE CONTROL IMSI:901700000010650
1550- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1551- ...ik=27497388b6cb044648f396aa155b95ef
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001552DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001553DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001554DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1555DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001556 security_mode_ctrl_sent == 1
1557 lu_result_sent == 0
1558- MS sends SecurityModeControl acceptance, VLR accepts and sends GSUP LU Req to HLR
1559DMM <- SECURITY MODE COMPLETE IMSI:901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001560DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: Received Event VLR_ULA_E_CIPH_RES
1561DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph()
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001562DIUCS IMSI:901700000010650: tx CommonID 901700000010650
1563- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001564DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4()
1565DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD
1566DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated
1567DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
1568DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START
Neels Hofmeyrd0756b12018-09-28 02:41:39 +02001569DVLR GSUP tx: 04010809710000000156f0280102
1570GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0280102
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001571DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001572 gsup_tx_confirmed == 1
1573 lu_result_sent == 0
1574- HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT
1575<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: 10010809710000000156f00804032443f2
1576DVLR GSUP rx 17: 10010809710000000156f00804032443f2
1577DREF VLR subscr IMSI:901700000010650 usage increases to: 2
1578DVLR IMSI:901700000010650 has MSISDN:42342
1579DVLR SUBSCR(MSISDN:42342) VLR: update for IMSI=901700000010650 (MSISDN=42342, used=2)
1580DVLR GSUP tx: 12010809710000000156f0
1581GSUP --> HLR: OSMO_GSUP_MSGT_INSERT_DATA_RESULT: 12010809710000000156f0
1582DREF VLR subscr MSISDN:42342 usage decreases to: 1
1583<-- GSUP rx OSMO_GSUP_MSGT_INSERT_DATA_REQUEST: vlr_gsupc_read_cb() returns 0
1584 lu_result_sent == 0
1585- HLR also sends GSUP _UPDATE_LOCATION_RESULT
1586<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: 06010809710000000156f0
1587DVLR GSUP rx 11: 06010809710000000156f0
1588DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001589DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES
1590DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK
1591DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE
1592DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1593DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1594DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance
1595DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated
1596DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL
1597DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL
1598DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated
1599DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650)
1600DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START
1601DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES
1602DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Allocated
1603DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000010650)
1604DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START
1605DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE
1606DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1607DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000010650)
1608DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance
1609DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated
1610DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL
1611DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi()
1612DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001613- sending LU Accept for MSISDN:42342, with TMSI 0x03020100
1614DREF VLR subscr MSISDN:42342 usage decreases to: 1
1615<-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0
1616 lu_result_sent == 1
1617- a LU Accept with a new TMSI was sent, waiting for TMSI Realloc Compl
1618 llist_count(&net->subscr_conns) == 1
1619msc_subscr_conn_is_accepted() == false
1620- MS sends TMSI Realloc Complete
1621 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_TMSI_REALL_COMPL
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001622DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001623DRLL Dispatching 04.08 message GSM48_MT_MM_TMSI_REALL_COMPL (0x5:0x1b)
1624DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001625DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK
1626DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001627DREF VLR subscr MSISDN:42342 usage increases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001628DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE
1629DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS
1630DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1631DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650)
1632DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance
1633DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated
1634DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE
1635DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
1636DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1637DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED
1638DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001639DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001640DREF VLR subscr MSISDN:42342 usage increases to: 3
1641DREF VLR subscr MSISDN:42342 usage decreases to: 2
1642- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001643DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release)
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001644 iu_release_sent == 1
1645- LU was successful, and the conn has already been closed
1646- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001647DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001648DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1649DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1650DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1651DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1652DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000010650)
1653DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT
1654DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Freeing instance
1655DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001656DRLL MSISDN:42342: Freeing subscriber connection
1657DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001658DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1659DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001660 llist_count(&net->subscr_conns) == 0
1661DREF VLR subscr MSISDN:42342 usage increases to: 2
1662 vsub != NULL == 1
1663 strcmp(vsub->imsi, IMSI) == 0
1664 vsub->lac == 23
1665DREF VLR subscr MSISDN:42342 usage decreases to: 1
1666---
1667- after a while, a new conn sends a CM Service Request. VLR responds with Auth Req, 2nd auth vector
1668 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_CM_SERV_REQ
1669 new conn
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001670DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001671DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001672DRLL Dispatching 04.08 message GSM48_MT_MM_CM_SERV_REQ (0x5:0x24)
1673DMM <- CM SERVICE REQUEST serv_type=0x08 MI(IMSI)=901700000010650
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001674DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Updated ID
1675DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Allocated
1676DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: is child of Subscr_Conn(CM_SERVICE_REQ:901700000010650)
1677DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
1678DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001679DREF VLR subscr MSISDN:42342 usage increases to: 2
1680DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001681DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
1682DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH
1683DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated
1684DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
1685DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
1686DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP
1687DVLR VLR_Authenticate(CM_SERVICE_REQ: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 Hofmeyreb1cfdb2018-03-15 13:42:10 +01001688- sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=1 auth_types=0x3 and...
1689- ...rand=c187a53a5e6b9d573cac7c74451fd46d
1690- ...autn=1843a645b98d00005b2d666af46c45d9
1691- ...expecting res=7db47cf7f81e4dc7
1692DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001693DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3
1694DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001695DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001696DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1697DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001698 cm_service_result_sent == 0
1699 auth_request_sent == 1
1700- needs auth, not yet accepted
1701msc_subscr_conn_is_accepted() == false
1702- MS sends Authen Response, VLR accepts and sends SecurityModeControl
1703 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_MM_AUTH_RESP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001704DREF MSISDN:42342: MSC conn use + dtap == 1 (0x2: dtap)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001705DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14)
1706DMM MSISDN:42342: MM UMTS AUTHENTICATION RESPONSE (res = 7db47cf7f81e4dc7)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001707DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001708DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes)
1709DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context
Neels Hofmeyr15809592018-04-06 02:57:51 +02001710DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001711DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED
1712DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1713DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650)
1714DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance
1715DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Deallocated
1716DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001717DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
1718DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001719DMM -> SECURITY MODE CONTROL MSISDN:42342
1720- sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1
1721- ...ik=1159ec926a50e98c034a6b7d7c9f418d
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001722DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001723DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001724DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED
1725DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001726 security_mode_ctrl_sent == 1
1727 cm_service_result_sent == 0
1728- MS sends SecurityModeControl acceptance, VLR accepts; above Ciphering is an implicit CM Service Accept
1729DMM <- SECURITY MODE COMPLETE MSISDN:42342
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001730DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
1731DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001732DIUCS MSISDN:42342: tx CommonID 901700000010650
1733- Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001734DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
1735DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
1736DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
1737DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
Neels Hofmeyr15809592018-04-06 02:57:51 +02001738DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001739DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE
Neels Hofmeyr15809592018-04-06 02:57:51 +02001740DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001741DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001742DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service)
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001743DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED
1744DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: subscr_conn_fsm_has_active_transactions: still awaiting first request after a CM Service Request
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001745 cm_service_result_sent == 0
1746---
1747- a call is initiated
1748- SETUP gets forwarded to MNCC
1749 MSC <--RAN_UTRAN_IU-- MS: GSM48_MT_CC_SETUP
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001750DREF MSISDN:42342: MSC conn use + dtap == 2 (0xa: dtap,cm_service)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001751DRLL Dispatching 04.08 message GSM48_MT_CC_SETUP (0x3:0x5)
1752DCC Unknown transaction ID 8, creating new trans.
1753DCC (ti 08 sub MSISDN:42342 callref 80000003) New transaction
1754DREF VLR subscr MSISDN:42342 usage increases to: 3
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001755DREF MSISDN:42342: MSC conn use + trans_cc == 3 (0x1a: dtap,cm_service,trans_cc)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001756DMM MSISDN:42342: rx msg GSM48_MT_CC_SETUP: received_cm_service_request changes to false
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001757DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x12: dtap,trans_cc)
Philipp Maier9ca7b312018-10-10 17:00:49 +02001758DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001759DCC (ti 08 sub MSISDN:42342) new state NULL -> INITIATED
1760DCC Subscriber MSISDN:42342 (42342) sends SETUP to 123
1761DMNCC transmit message MNCC_SETUP_IND
1762DCC Sending 'MNCC_SETUP_IND' to MNCC.
1763 MSC --> MNCC: callref 0x80000003: MNCC_SETUP_IND
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001764DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING
1765DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001766DREF MSISDN:42342: MSC conn use - dtap == 1 (0x10: trans_cc)
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001767- MNCC says that's fine
1768DMNCC receive message MNCC_CALL_PROC_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +02001769DCC (sub 42342) stopping pending guard timer
1770DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001771DCC (ti 08 sub 42342) Received 'MNCC_CALL_PROC_REQ' from MNCC in state 1 (INITIATED)
1772DCC (ti 08 sub MSISDN:42342) new state INITIATED -> MO_CALL_PROC
1773DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1774- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_CALL_PROC: 8302
1775- DTAP matches expected message
1776 MS <--Call Assignment-- MSC: subscr=MSISDN:42342 callref=0x80000003
1777- But the other side's MSISDN could not be resolved, MNCC tells us to cancel
1778DMNCC receive message MNCC_REL_REQ
Philipp Maier9ca7b312018-10-10 17:00:49 +02001779DCC (sub 42342) stopping pending guard timer
1780DCC (sub 42342) starting guard timer with 180 seconds
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001781DCC (ti 08 sub 42342) Received 'MNCC_REL_REQ' from MNCC in state 3 (MO_CALL_PROC)
1782DCC starting timer T308 with 10 seconds
1783DCC (ti 08 sub MSISDN:42342) new state MO_CALL_PROC -> RELEASE_REQ
1784DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1785- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d
1786- DTAP matches expected message
1787- Despite our repeated CC Release Requests, the MS does not respond anymore
1788- Total time passed: 10.000023 s
1789DCC starting timer T308 with 10 seconds
1790DMSC msc_tx 2 bytes to MSISDN:42342 via RAN_UTRAN_IU
1791- DTAP --RAN_UTRAN_IU--> MS: GSM48_MT_CC_RELEASE: 832d
1792- DTAP matches expected message
1793- The CC Release times out and we still properly clear the conn
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001794- Total time passed: 20.000046 s
1795 MS <--Call Release-- MSC: subscr=MSISDN:42342 callref=0x80000003
1796DMNCC transmit message MNCC_REL_CNF
1797DCC Sending 'MNCC_REL_CNF' to MNCC.
1798 MSC --> MNCC: callref 0x80000003: MNCC_REL_CNF
1799DCC (ti 08 sub MSISDN:42342) new state RELEASE_REQ -> NULL
Philipp Maier9ca7b312018-10-10 17:00:49 +02001800DCC (sub 42342) stopping pending guard timer
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001801DREF VLR subscr MSISDN:42342 usage decreases to: 2
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001802DREF MSISDN:42342: MSC conn use - trans_cc == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001803DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED
1804DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001805DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release)
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001806DREF VLR subscr MSISDN:42342 usage increases to: 3
1807DREF VLR subscr MSISDN:42342 usage decreases to: 2
1808- Iu Release --RAN_UTRAN_IU--> MS
Neels Hofmeyr4068ab22018-04-01 20:55:54 +02001809- RNC sends Iu Release Complete
Neels Hofmeyr99a8d232018-04-09 20:44:56 +02001810DREF MSISDN:42342: MSC conn use - release == 0 (0x0: )
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001811DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED
1812DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED
1813DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
1814DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT)
1815DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650)
1816DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Freeing instance
1817DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Deallocated
Neels Hofmeyre3d3dc62018-03-31 00:02:14 +02001818DRLL MSISDN:42342: Freeing subscriber connection
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001819DREF VLR subscr MSISDN:42342 usage decreases to: 1
Neels Hofmeyrfe4ba7c2018-04-02 23:17:50 +02001820DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Freeing instance
1821DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Deallocated
Neels Hofmeyrd6a769b2018-03-12 23:59:07 +01001822 llist_count(&net->subscr_conns) == 0
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001823DREF freeing VLR subscr MSISDN:42342
1824===== test_call_mo_to_unknown_timeout: SUCCESS
1825
1826full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001827talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyreb1cfdb2018-03-15 13:42:10 +01001828
Neels Hofmeyra99b4272017-11-21 17:13:23 +01001829full talloc report on 'msgb' (total 0 bytes in 1 blocks)
Neels Hofmeyr08b38282018-03-30 23:04:04 +02001830talloc_total_blocks(tall_bsc_ctx) == 12
Neels Hofmeyra99b4272017-11-21 17:13:23 +01001831