diff options
Diffstat (limited to 'tests/msc_vlr/msc_vlr_test_authen_reuse.err')
| -rw-r--r-- | tests/msc_vlr/msc_vlr_test_authen_reuse.err | 470 |
1 files changed, 235 insertions, 235 deletions
diff --git a/tests/msc_vlr/msc_vlr_test_authen_reuse.err b/tests/msc_vlr/msc_vlr_test_authen_reuse.err index 2fae41810..c989ea547 100644 --- a/tests/msc_vlr/msc_vlr_test_authen_reuse.err +++ b/tests/msc_vlr/msc_vlr_test_authen_reuse.err @@ -21,15 +21,15 @@ DVLR New subscr, IMSI: 901700000010650 DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DREF VLR subscr IMSI:901700000010650 usage decreases to: 1 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: State change to VLR_ULA_S_WAIT_AUTH (T0, 30s) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START DVLR GSUP tx: 08010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI (T0, 30s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -40,7 +40,7 @@ DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR 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) - sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -59,7 +59,7 @@ DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -68,13 +68,13 @@ DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth() DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph() DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: State change to VLR_ULA_S_WAIT_HLR_UPD (T0, 30s) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START DVLR GSUP tx: 04010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0 -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: State change to UPD_HLR_VLR_S_WAIT_FOR_DATA (T0, 30s) DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -97,28 +97,28 @@ DVLR GSUP rx 11: 06010809710000000156f0 DREF VLR subscr MSISDN:42342 usage increases to: 2 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: State change to UPD_HLR_VLR_S_DONE (no timeout) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: State change to VLR_ULA_S_WAIT_LU_COMPL (T0, 30s) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: State change to LU_COMPL_VLR_S_WAIT_SUB_PRES (T0, 30s) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Allocated DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START -DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE +DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: State change to SUB_PRES_VLR_S_DONE (no timeout) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi() -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: State change to LU_COMPL_VLR_S_WAIT_TMSI_CNF (no timeout) - sending LU Accept for MSISDN:42342, with TMSI 0x03020100 DREF VLR subscr MSISDN:42342 usage decreases to: 1 <-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0 @@ -150,17 +150,17 @@ DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK DREF VLR subscr MSISDN:42342 usage increases to: 2 -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: State change to LU_COMPL_VLR_S_DONE (no timeout) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: State change to VLR_ULA_S_DONE (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -170,7 +170,7 @@ DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release) - BSS sends BSSMAP Clear Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000010650) @@ -204,11 +204,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=2 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=2 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -216,7 +216,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got - ...expecting res=e229c19e791f2e41 DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -231,7 +231,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -244,12 +244,12 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED - sending CM Service Accept for MSISDN:42342 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 2 (0xa: dtap,cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 DREF MSISDN:42342: MSC conn use - dtap == 1 (0x8: cm_service) cm_service_result_sent == 1 @@ -267,7 +267,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A @@ -277,7 +277,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -286,7 +286,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - BSS sends BSSMAP Clear Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -319,16 +319,16 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START DVLR GSUP tx: 08010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI (T0, 30s) DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -341,7 +341,7 @@ DVLR GSUP rx 111: 0a010809710000000156f003622010c187a53a5e6b9d573cac7c74451fd46d DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK DVLR SUBSCR(MSISDN:42342) Received 1 auth tuples -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ: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) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=0 auth_types=0x3 and... - ...rand=c187a53a5e6b9d573cac7c74451fd46d @@ -360,7 +360,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 7db47cf7f81e4dc7 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -373,12 +373,12 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED - sending CM Service Accept for MSISDN:42342 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 2 (0xa: dtap,cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 DREF MSISDN:42342: MSC conn use - dtap == 1 (0x8: cm_service) cm_service_result_sent == 1 @@ -396,7 +396,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A @@ -406,7 +406,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -415,7 +415,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - BSS sends BSSMAP Clear Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -443,7 +443,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 1 DREF VLR subscr MSISDN:42342 usage decreases to: 0 DREF freeing VLR subscr MSISDN:42342 DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE -DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF unknown: MSC conn use + release == 2 (0x101: compl_l3,release) - BSSAP Clear --RAN_GERAN_A--> MS DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) @@ -451,7 +451,7 @@ DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) - BSS sends BSSMAP Clear Complete DREF unknown: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DRLL Freeing subscriber connection with NULL subscriber DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance @@ -482,15 +482,15 @@ DVLR New subscr, IMSI: 901700000010650 DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DREF VLR subscr IMSI:901700000010650 usage decreases to: 1 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: State change to VLR_ULA_S_WAIT_AUTH (T0, 30s) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START DVLR GSUP tx: 08010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI (T0, 30s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -501,7 +501,7 @@ DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR 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) - sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -520,7 +520,7 @@ DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -531,7 +531,7 @@ DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode DMM -> SECURITY MODE CONTROL IMSI:901700000010650 - sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1 - ...ik=27497388b6cb044648f396aa155b95ef -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: State change to VLR_ULA_S_WAIT_CIPH (T0, 30s) DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -544,13 +544,13 @@ DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph( DIUCS IMSI:901700000010650: tx CommonID 901700000010650 - Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: State change to VLR_ULA_S_WAIT_HLR_UPD (T0, 30s) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START DVLR GSUP tx: 04010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0 -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: State change to UPD_HLR_VLR_S_WAIT_FOR_DATA (T0, 30s) gsup_tx_confirmed == 1 lu_result_sent == 0 - HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT @@ -570,28 +570,28 @@ DVLR GSUP rx 11: 06010809710000000156f0 DREF VLR subscr MSISDN:42342 usage increases to: 2 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: State change to UPD_HLR_VLR_S_DONE (no timeout) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: State change to VLR_ULA_S_WAIT_LU_COMPL (T0, 30s) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: State change to LU_COMPL_VLR_S_WAIT_SUB_PRES (T0, 30s) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Allocated DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START -DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE +DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: State change to SUB_PRES_VLR_S_DONE (no timeout) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi() -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: State change to LU_COMPL_VLR_S_WAIT_TMSI_CNF (no timeout) - sending LU Accept for MSISDN:42342, with TMSI 0x03020100 DREF VLR subscr MSISDN:42342 usage decreases to: 1 <-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0 @@ -623,17 +623,17 @@ DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK DREF VLR subscr MSISDN:42342 usage increases to: 2 -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: State change to LU_COMPL_VLR_S_DONE (no timeout) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: State change to VLR_ULA_S_DONE (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -643,7 +643,7 @@ DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release) - RNC sends Iu Release Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000010650) @@ -677,11 +677,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=2 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=2 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -689,7 +689,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got - ...expecting res=e229c19e791f2e41 DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -704,7 +704,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -715,7 +715,7 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DMM -> SECURITY MODE CONTROL MSISDN:42342 - sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1 - ...ik=27497388b6cb044648f396aa155b95ef -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_WAIT_CIPH (no timeout) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -732,11 +732,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CI DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 cm_service_result_sent == 0 - a USSD request is serviced @@ -753,7 +753,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_UTRAN_IU @@ -763,7 +763,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -772,7 +772,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - RNC sends Iu Release Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -805,16 +805,16 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START DVLR GSUP tx: 08010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI (T0, 30s) DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -827,7 +827,7 @@ DVLR GSUP rx 111: 0a010809710000000156f003622010c187a53a5e6b9d573cac7c74451fd46d DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK DVLR SUBSCR(MSISDN:42342) Received 1 auth tuples -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ: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) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=0 auth_types=0x3 and... - ...rand=c187a53a5e6b9d573cac7c74451fd46d @@ -846,7 +846,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -857,7 +857,7 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DMM -> SECURITY MODE CONTROL MSISDN:42342 - sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1 - ...ik=1159ec926a50e98c034a6b7d7c9f418d -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_WAIT_CIPH (no timeout) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -874,11 +874,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CI DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 cm_service_result_sent == 0 - a USSD request is serviced @@ -895,7 +895,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_UTRAN_IU @@ -905,7 +905,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -914,7 +914,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - RNC sends Iu Release Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -942,7 +942,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 1 DREF VLR subscr MSISDN:42342 usage decreases to: 0 DREF freeing VLR subscr MSISDN:42342 DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE -DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF unknown: MSC conn use + release == 2 (0x101: compl_l3,release) - Iu Release --RAN_UTRAN_IU--> MS DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) @@ -950,7 +950,7 @@ DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) - RNC sends Iu Release Complete DREF unknown: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DRLL Freeing subscriber connection with NULL subscriber DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance @@ -981,15 +981,15 @@ DVLR New subscr, IMSI: 901700000010650 DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DREF VLR subscr IMSI:901700000010650 usage decreases to: 1 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: State change to VLR_ULA_S_WAIT_AUTH (T0, 30s) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START DVLR GSUP tx: 08010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI (T0, 30s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -1000,7 +1000,7 @@ DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR 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) - sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -1019,7 +1019,7 @@ DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -1028,13 +1028,13 @@ DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth() DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph() DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: State change to VLR_ULA_S_WAIT_HLR_UPD (T0, 30s) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START DVLR GSUP tx: 04010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0 -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: State change to UPD_HLR_VLR_S_WAIT_FOR_DATA (T0, 30s) DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -1057,28 +1057,28 @@ DVLR GSUP rx 11: 06010809710000000156f0 DREF VLR subscr MSISDN:42342 usage increases to: 2 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: State change to UPD_HLR_VLR_S_DONE (no timeout) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: State change to VLR_ULA_S_WAIT_LU_COMPL (T0, 30s) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: State change to LU_COMPL_VLR_S_WAIT_SUB_PRES (T0, 30s) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Allocated DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START -DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE +DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: State change to SUB_PRES_VLR_S_DONE (no timeout) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi() -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: State change to LU_COMPL_VLR_S_WAIT_TMSI_CNF (no timeout) - sending LU Accept for MSISDN:42342, with TMSI 0x03020100 DREF VLR subscr MSISDN:42342 usage decreases to: 1 <-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0 @@ -1110,17 +1110,17 @@ DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK DREF VLR subscr MSISDN:42342 usage increases to: 2 -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: State change to LU_COMPL_VLR_S_DONE (no timeout) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: State change to VLR_ULA_S_DONE (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -1130,7 +1130,7 @@ DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release) - BSS sends BSSMAP Clear Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000010650) @@ -1164,11 +1164,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=2 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=2 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -1176,7 +1176,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got - ...expecting res=e229c19e791f2e41 DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -1191,7 +1191,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -1204,12 +1204,12 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED - sending CM Service Accept for MSISDN:42342 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 2 (0xa: dtap,cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 DREF MSISDN:42342: MSC conn use - dtap == 1 (0x8: cm_service) cm_service_result_sent == 1 @@ -1227,7 +1227,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A @@ -1237,7 +1237,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -1246,7 +1246,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - BSS sends BSSMAP Clear Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -1279,11 +1279,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=3 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=3 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -1291,7 +1291,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got - ...expecting res=e229c19e791f2e41 DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -1306,7 +1306,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -1319,12 +1319,12 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED - sending CM Service Accept for MSISDN:42342 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 2 (0xa: dtap,cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 DREF MSISDN:42342: MSC conn use - dtap == 1 (0x8: cm_service) cm_service_result_sent == 1 @@ -1342,7 +1342,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A @@ -1352,7 +1352,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -1361,7 +1361,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - BSS sends BSSMAP Clear Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -1394,11 +1394,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=4 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=4 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -1406,7 +1406,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got - ...expecting res=e229c19e791f2e41 DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -1421,7 +1421,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -1434,12 +1434,12 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED - sending CM Service Accept for MSISDN:42342 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 2 (0xa: dtap,cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 DREF MSISDN:42342: MSC conn use - dtap == 1 (0x8: cm_service) cm_service_result_sent == 1 @@ -1457,7 +1457,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A @@ -1467,7 +1467,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -1476,7 +1476,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - BSS sends BSSMAP Clear Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -1504,7 +1504,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 1 DREF VLR subscr MSISDN:42342 usage decreases to: 0 DREF freeing VLR subscr MSISDN:42342 DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE -DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF unknown: MSC conn use + release == 2 (0x101: compl_l3,release) - BSSAP Clear --RAN_GERAN_A--> MS DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) @@ -1512,7 +1512,7 @@ DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) - BSS sends BSSMAP Clear Complete DREF unknown: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DRLL Freeing subscriber connection with NULL subscriber DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance @@ -1543,15 +1543,15 @@ DVLR New subscr, IMSI: 901700000010650 DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DREF VLR subscr IMSI:901700000010650 usage decreases to: 1 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: State change to VLR_ULA_S_WAIT_AUTH (T0, 30s) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START DVLR GSUP tx: 08010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI (T0, 30s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -1562,7 +1562,7 @@ DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR 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) - sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -1581,7 +1581,7 @@ DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -1592,7 +1592,7 @@ DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode DMM -> SECURITY MODE CONTROL IMSI:901700000010650 - sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1 - ...ik=27497388b6cb044648f396aa155b95ef -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: State change to VLR_ULA_S_WAIT_CIPH (T0, 30s) DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -1605,13 +1605,13 @@ DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph( DIUCS IMSI:901700000010650: tx CommonID 901700000010650 - Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: State change to VLR_ULA_S_WAIT_HLR_UPD (T0, 30s) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START DVLR GSUP tx: 04010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0 -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: State change to UPD_HLR_VLR_S_WAIT_FOR_DATA (T0, 30s) gsup_tx_confirmed == 1 lu_result_sent == 0 - HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT @@ -1631,28 +1631,28 @@ DVLR GSUP rx 11: 06010809710000000156f0 DREF VLR subscr MSISDN:42342 usage increases to: 2 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: State change to UPD_HLR_VLR_S_DONE (no timeout) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: State change to VLR_ULA_S_WAIT_LU_COMPL (T0, 30s) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: State change to LU_COMPL_VLR_S_WAIT_SUB_PRES (T0, 30s) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Allocated DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START -DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE +DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: State change to SUB_PRES_VLR_S_DONE (no timeout) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi() -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: State change to LU_COMPL_VLR_S_WAIT_TMSI_CNF (no timeout) - sending LU Accept for MSISDN:42342, with TMSI 0x03020100 DREF VLR subscr MSISDN:42342 usage decreases to: 1 <-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0 @@ -1684,17 +1684,17 @@ DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK DREF VLR subscr MSISDN:42342 usage increases to: 2 -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: State change to LU_COMPL_VLR_S_DONE (no timeout) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: State change to VLR_ULA_S_DONE (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -1704,7 +1704,7 @@ DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release) - RNC sends Iu Release Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000010650) @@ -1738,11 +1738,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=2 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=2 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -1750,7 +1750,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got - ...expecting res=e229c19e791f2e41 DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -1765,7 +1765,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -1776,7 +1776,7 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DMM -> SECURITY MODE CONTROL MSISDN:42342 - sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1 - ...ik=27497388b6cb044648f396aa155b95ef -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_WAIT_CIPH (no timeout) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -1793,11 +1793,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CI DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 cm_service_result_sent == 0 - a USSD request is serviced @@ -1814,7 +1814,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_UTRAN_IU @@ -1824,7 +1824,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -1833,7 +1833,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - RNC sends Iu Release Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -1866,11 +1866,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=3 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=3 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -1878,7 +1878,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got - ...expecting res=e229c19e791f2e41 DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -1893,7 +1893,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -1904,7 +1904,7 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DMM -> SECURITY MODE CONTROL MSISDN:42342 - sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1 - ...ik=27497388b6cb044648f396aa155b95ef -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_WAIT_CIPH (no timeout) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -1921,11 +1921,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CI DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 cm_service_result_sent == 0 - a USSD request is serviced @@ -1942,7 +1942,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_UTRAN_IU @@ -1952,7 +1952,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -1961,7 +1961,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - RNC sends Iu Release Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -1994,11 +1994,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=4 key_seq=0 -- will use UMTS AKA (is_r99=yes, at->vec.auth_types=0x3) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=4 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -2006,7 +2006,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: got - ...expecting res=e229c19e791f2e41 DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -2021,7 +2021,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -2032,7 +2032,7 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DMM -> SECURITY MODE CONTROL MSISDN:42342 - sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1 - ...ik=27497388b6cb044648f396aa155b95ef -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_WAIT_CIPH (no timeout) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -2049,11 +2049,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CI DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 cm_service_result_sent == 0 - a USSD request is serviced @@ -2070,7 +2070,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_UTRAN_IU @@ -2080,7 +2080,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -2089,7 +2089,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - RNC sends Iu Release Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -2117,7 +2117,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 1 DREF VLR subscr MSISDN:42342 usage decreases to: 0 DREF freeing VLR subscr MSISDN:42342 DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE -DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF unknown: MSC conn use + release == 2 (0x101: compl_l3,release) - Iu Release --RAN_UTRAN_IU--> MS DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) @@ -2125,7 +2125,7 @@ DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) - RNC sends Iu Release Complete DREF unknown: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DRLL Freeing subscriber connection with NULL subscriber DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance @@ -2156,15 +2156,15 @@ DVLR New subscr, IMSI: 901700000010650 DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DREF VLR subscr IMSI:901700000010650 usage decreases to: 1 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: State change to VLR_ULA_S_WAIT_AUTH (T0, 30s) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START DVLR GSUP tx: 08010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI (T0, 30s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -2175,7 +2175,7 @@ DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR 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) - sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -2194,7 +2194,7 @@ DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event DVLR SUBSCR(IMSI:901700000010650) AUTH on GERAN received SRES/RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -2203,13 +2203,13 @@ DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth() DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_ciph() DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_node_4() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: State change to VLR_ULA_S_WAIT_HLR_UPD (T0, 30s) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START DVLR GSUP tx: 04010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0 -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: State change to UPD_HLR_VLR_S_WAIT_FOR_DATA (T0, 30s) DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -2232,28 +2232,28 @@ DVLR GSUP rx 11: 06010809710000000156f0 DREF VLR subscr MSISDN:42342 usage increases to: 2 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: State change to UPD_HLR_VLR_S_DONE (no timeout) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: State change to VLR_ULA_S_WAIT_LU_COMPL (T0, 30s) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: State change to LU_COMPL_VLR_S_WAIT_SUB_PRES (T0, 30s) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Allocated DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START -DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE +DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: State change to SUB_PRES_VLR_S_DONE (no timeout) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi() -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: State change to LU_COMPL_VLR_S_WAIT_TMSI_CNF (no timeout) - sending LU Accept for MSISDN:42342, with TMSI 0x03020100 DREF VLR subscr MSISDN:42342 usage decreases to: 1 <-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0 @@ -2285,17 +2285,17 @@ DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK DREF VLR subscr MSISDN:42342 usage increases to: 2 -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: State change to LU_COMPL_VLR_S_DONE (no timeout) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: State change to VLR_ULA_S_DONE (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -2305,7 +2305,7 @@ DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release) - BSS sends BSSMAP Clear Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000010650) @@ -2339,16 +2339,16 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START DVLR GSUP tx: 08010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI (T0, 30s) DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -2361,7 +2361,7 @@ DVLR GSUP rx 111: 0a010809710000000156f003622010c187a53a5e6b9d573cac7c74451fd46d DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK DVLR SUBSCR(MSISDN:42342) Received 1 auth tuples -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ: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) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=0 auth_types=0x3 and... - ...rand=c187a53a5e6b9d573cac7c74451fd46d @@ -2380,7 +2380,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on GERAN received SRES/RES: 7db47cf7f81e4dc7 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -2393,12 +2393,12 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED - sending CM Service Accept for MSISDN:42342 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 2 (0xa: dtap,cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 DREF MSISDN:42342: MSC conn use - dtap == 1 (0x8: cm_service) cm_service_result_sent == 1 @@ -2416,7 +2416,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_GERAN_A @@ -2426,7 +2426,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -2435,7 +2435,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - BSS sends BSSMAP Clear Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -2463,7 +2463,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 1 DREF VLR subscr MSISDN:42342 usage decreases to: 0 DREF freeing VLR subscr MSISDN:42342 DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE -DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF unknown: MSC conn use + release == 2 (0x101: compl_l3,release) - BSSAP Clear --RAN_GERAN_A--> MS DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) @@ -2471,7 +2471,7 @@ DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) - BSS sends BSSMAP Clear Complete DREF unknown: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DRLL Freeing subscriber connection with NULL subscriber DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance @@ -2502,15 +2502,15 @@ DVLR New subscr, IMSI: 901700000010650 DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DREF VLR subscr IMSI:901700000010650 usage decreases to: 1 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: vlr_loc_upd_node1() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_IDLE}: State change to VLR_ULA_S_WAIT_AUTH (T0, 30s) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START DVLR GSUP tx: 08010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI (T0, 30s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF IMSI:901700000010650: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -2521,7 +2521,7 @@ DVLR GSUP rx 111: 0a010809710000000156f00362201039fa2f4e3d523d8619a73b4f65c3e14d DREF VLR subscr IMSI:901700000010650 usage increases to: 2 DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK DVLR SUBSCR(IMSI:901700000010650) Received 1 auth tuples -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR 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) - sending UMTS Auth Request for IMSI:901700000010650: tuple use_count=1 key_seq=0 auth_types=0x3 and... - ...rand=39fa2f4e3d523d8619a73b4f65c3e14d @@ -2540,7 +2540,7 @@ DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Received Event DVLR SUBSCR(IMSI:901700000010650) AUTH on UTRAN received RES: e229c19e791f2e41 (8 bytes) DVLR SUBSCR(IMSI:901700000010650) AUTH established UMTS security context DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR VLR_Authenticate(LU:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -2551,7 +2551,7 @@ DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode DMM -> SECURITY MODE CONTROL IMSI:901700000010650 - sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1 - ...ik=27497388b6cb044648f396aa155b95ef -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_AUTH}: State change to VLR_ULA_S_WAIT_CIPH (T0, 30s) DREF IMSI:901700000010650: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -2564,13 +2564,13 @@ DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_post_ciph( DIUCS IMSI:901700000010650: tx CommonID 901700000010650 - Iu Common ID --RAN_UTRAN_IU--> MS (IMSI=901700000010650) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: vlr_loc_upd_node_4() -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_WAIT_HLR_UPD +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_CIPH}: State change to VLR_ULA_S_WAIT_HLR_UPD (T0, 30s) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Allocated DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: Received Event UPD_HLR_VLR_E_START DVLR GSUP tx: 04010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_UPDATE_LOCATION_REQUEST: 04010809710000000156f0 -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: state_chg to UPD_HLR_VLR_S_WAIT_FOR_DATA +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_INIT}: State change to UPD_HLR_VLR_S_WAIT_FOR_DATA (T0, 30s) gsup_tx_confirmed == 1 lu_result_sent == 0 - HLR sends _INSERT_DATA_REQUEST, VLR responds with _INSERT_DATA_RESULT @@ -2590,28 +2590,28 @@ DVLR GSUP rx 11: 06010809710000000156f0 DREF VLR subscr MSISDN:42342 usage increases to: 2 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_HLR_LU_RES DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: Received Event UPD_HLR_VLR_E_UPD_LOC_ACK -DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: state_chg to UPD_HLR_VLR_S_DONE +DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_WAIT_FOR_DATA}: State change to UPD_HLR_VLR_S_DONE (no timeout) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Freeing instance DVLR upd_hlr_vlr_fsm(LU:901700000010650){UPD_HLR_VLR_S_DONE}: Deallocated DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: Received Event VLR_ULA_E_UPD_HLR_COMPL -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: state_chg to VLR_ULA_S_WAIT_LU_COMPL +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_HLR_UPD}: State change to VLR_ULA_S_WAIT_LU_COMPL (T0, 30s) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Allocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: is child of vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: Received Event LU_COMPL_VLR_E_START -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: state_chg to LU_COMPL_VLR_S_WAIT_SUB_PRES +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_INIT}: State change to LU_COMPL_VLR_S_WAIT_SUB_PRES (T0, 30s) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Allocated DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: is child of lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: Received Event SUB_PRES_VLR_E_START -DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: state_chg to SUB_PRES_VLR_S_DONE +DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_INIT}: State change to SUB_PRES_VLR_S_DONE (no timeout) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Removing from parent lu_compl_vlr_fsm(LU:901700000010650) DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Freeing instance DVLR sub_pres_vlr_fsm(LU:901700000010650){SUB_PRES_VLR_S_DONE}: Deallocated DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: Received Event LU_COMPL_VLR_E_SUB_PRES_COMPL DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: lu_compl_vlr_new_tmsi() -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: state_chg to LU_COMPL_VLR_S_WAIT_TMSI_CNF +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_SUB_PRES}: State change to LU_COMPL_VLR_S_WAIT_TMSI_CNF (no timeout) - sending LU Accept for MSISDN:42342, with TMSI 0x03020100 DREF VLR subscr MSISDN:42342 usage decreases to: 1 <-- GSUP rx OSMO_GSUP_MSGT_UPDATE_LOCATION_RESULT: vlr_gsupc_read_cb() returns 0 @@ -2643,17 +2643,17 @@ DMM TMSI Reallocation Completed. Subscriber: MSISDN:42342 DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_NEW_TMSI_ACK DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: Received Event LU_COMPL_VLR_E_NEW_TMSI_ACK DREF VLR subscr MSISDN:42342 usage increases to: 2 -DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: state_chg to LU_COMPL_VLR_S_DONE +DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_WAIT_TMSI_CNF}: State change to LU_COMPL_VLR_S_DONE (no timeout) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: Received Event VLR_ULA_E_LU_COMPL_SUCCESS DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Removing from parent vlr_lu_fsm(LU:901700000010650) DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Freeing instance DVLR lu_compl_vlr_fsm(LU:901700000010650){LU_COMPL_VLR_S_DONE}: Deallocated -DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: state_chg to VLR_ULA_S_DONE +DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_WAIT_LU_COMPL}: State change to VLR_ULA_S_DONE (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 2 (0x102: dtap,release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -2663,7 +2663,7 @@ DREF MSISDN:42342: MSC conn use - dtap == 1 (0x100: release) - RNC sends Iu Release Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(LU:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR vlr_lu_fsm(LU:901700000010650){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000010650) @@ -2697,16 +2697,16 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: DREF VLR subscr MSISDN:42342 usage increases to: 2 DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi() -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: state_chg to PR_ARQ_S_WAIT_AUTH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Allocated DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START DVLR GSUP tx: 08010809710000000156f0 GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000000156f0 -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI (T0, 30s) DREF VLR subscr MSISDN:42342 usage decreases to: 2 DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_AUTH_CIPH (T0, 5s) DREF MSISDN:42342: MSC conn use - compl_l3 == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -2719,7 +2719,7 @@ DVLR GSUP rx 111: 0a010809710000000156f003622010c187a53a5e6b9d573cac7c74451fd46d DREF VLR subscr MSISDN:42342 usage increases to: 3 DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK DVLR SUBSCR(MSISDN:42342) Received 1 auth tuples -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: State change to VLR_SUB_AS_WAIT_RESP (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ: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) - sending UMTS Auth Request for MSISDN:42342: tuple use_count=1 key_seq=0 auth_types=0x3 and... - ...rand=c187a53a5e6b9d573cac7c74451fd46d @@ -2738,7 +2738,7 @@ DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Rec DVLR SUBSCR(MSISDN:42342) AUTH on UTRAN received RES: 7db47cf7f81e4dc7 (8 bytes) DVLR SUBSCR(MSISDN:42342) AUTH established UMTS security context DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED -DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650) DVLR VLR_Authenticate(CM_SERVICE_REQ:901700000010650){VLR_SUB_AS_AUTHENTICATED}: Freeing instance @@ -2749,7 +2749,7 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AU DMM -> SECURITY MODE CONTROL MSISDN:42342 - sending SecurityModeControl for UE ctx 42 send_ck=0 new_key=1 - ...ik=1159ec926a50e98c034a6b7d7c9f418d -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: state_chg to PR_ARQ_S_WAIT_CIPH +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_WAIT_CIPH (no timeout) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED @@ -2766,11 +2766,11 @@ DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CI DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei() DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED) -DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: state_chg to PR_ARQ_S_DONE +DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_WAIT_CIPH}: State change to PR_ARQ_S_DONE (no timeout) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Process Access Request result: PASSED DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_ACCEPTED DREF MSISDN:42342: MSC conn use + cm_service == 1 (0x8: cm_service) -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_ACCEPTED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_AUTH_CIPH}: State change to SUBSCR_CONN_S_ACCEPTED (T0, 5s) DMM 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 cm_service_result_sent == 0 - a USSD request is serviced @@ -2787,7 +2787,7 @@ DREF MSISDN:42342: MSC conn use + trans_nc_ss == 3 (0x4a: dtap,cm_service,trans_ DMM MSISDN:42342: rx msg GSM0480_MTYPE_REGISTER: received_cm_service_request changes to false DREF MSISDN:42342: MSC conn use - cm_service == 2 (0x42: dtap,trans_nc_ss) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: Received Event SUBSCR_CONN_E_COMMUNICATING -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: state_chg to SUBSCR_CONN_S_COMMUNICATING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_ACCEPTED}: State change to SUBSCR_CONN_S_COMMUNICATING (no timeout) DMM USSD: Own number requested DMM MSISDN:42342: MSISDN = 42342 DMSC msc_tx 43 bytes to MSISDN:42342 via RAN_UTRAN_IU @@ -2797,7 +2797,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 DREF MSISDN:42342: MSC conn use - trans_nc_ss == 1 (0x2: dtap) DREF MSISDN:42342: MSC conn use - dtap == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_COMMUNICATING}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF MSISDN:42342: MSC conn use + release == 1 (0x100: release) DREF VLR subscr MSISDN:42342 usage increases to: 3 DREF VLR subscr MSISDN:42342 usage decreases to: 2 @@ -2806,7 +2806,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 2 - RNC sends Iu Release Complete DREF MSISDN:42342: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn(CM_SERVICE_REQ:901700000010650){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) DVLR Process_Access_Request_VLR(CM_SERVICE_REQ:901700000010650){PR_ARQ_S_DONE}: Removing from parent Subscr_Conn(CM_SERVICE_REQ:901700000010650) @@ -2834,7 +2834,7 @@ DREF VLR subscr MSISDN:42342 usage decreases to: 1 DREF VLR subscr MSISDN:42342 usage decreases to: 0 DREF freeing VLR subscr MSISDN:42342 DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_CN_CLOSE -DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_RELEASING +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: State change to SUBSCR_CONN_S_RELEASING (T0, 5s) DREF unknown: MSC conn use + release == 2 (0x101: compl_l3,release) - Iu Release --RAN_UTRAN_IU--> MS DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) @@ -2842,7 +2842,7 @@ DREF unknown: MSC conn use - compl_l3 == 1 (0x100: release) - RNC sends Iu Release Complete DREF unknown: MSC conn use - release == 0 (0x0: ) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED -DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn{SUBSCR_CONN_S_RELEASING}: State change to SUBSCR_CONN_S_RELEASED (no timeout) DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) DRLL Freeing subscriber connection with NULL subscriber DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Freeing instance |