diff options
Diffstat (limited to 'tests/msc_vlr/msc_vlr_test_ms_timeout.err')
| -rw-r--r-- | tests/msc_vlr/msc_vlr_test_ms_timeout.err | 130 |
1 files changed, 130 insertions, 0 deletions
diff --git a/tests/msc_vlr/msc_vlr_test_ms_timeout.err b/tests/msc_vlr/msc_vlr_test_ms_timeout.err index eb40a97d2..43eb3d4a3 100644 --- a/tests/msc_vlr/msc_vlr_test_ms_timeout.err +++ b/tests/msc_vlr/msc_vlr_test_ms_timeout.err @@ -554,6 +554,136 @@ DMM Subscr_Conn{SUBSCR_CONN_S_RELEASED}: Deallocated full talloc report on 'msgb' (total 0 bytes in 1 blocks) talloc_total_blocks(tall_bsc_ctx) == 12 +===== test_classmark_update_timeout +- Total time passed: 0.000000 s +- Location Update request causes a GSUP Send Auth Info request to HLR + MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_LOC_UPD_REQUEST + new conn +DMM Subscr_Conn{SUBSCR_CONN_S_NEW}: Allocated +DREF unknown: MSC conn use + compl_l3 == 1 (0x1: compl_l3) +DRLL Dispatching 04.08 message GSM48_MT_MM_LOC_UPD_REQUEST (0x5:0x8) +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Updated ID +DMM LOCATION UPDATING REQUEST: MI(IMSI)=901700000004620 type=IMSI ATTACH +DMM LU/new-LAC: 1/23 +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Allocated +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: is child of Subscr_Conn(LU:901700000004620) +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: rev=GSM net=GERAN Auth+Ciph +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: Received Event VLR_ULA_E_UPDATE_LA +DREF VLR subscr unknown usage increases to: 1 +DVLR set IMSI on subscriber; IMSI=901700000004620 id=901700000004620 +DVLR New subscr, IMSI: 901700000004620 +DREF VLR subscr IMSI:901700000004620 usage increases to: 2 +DREF VLR subscr IMSI:901700000004620 usage decreases to: 1 +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: vlr_loc_upd_node1() +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_IDLE}: state_chg to VLR_ULA_S_WAIT_AUTH +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Allocated +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: is child of vlr_lu_fsm(LU:901700000004620) +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START +DVLR GSUP tx: 08010809710000004026f0 +GSUP --> HLR: OSMO_GSUP_MSGT_SEND_AUTH_INFO_REQUEST: 08010809710000004026f0 +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH}: state_chg to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: Received Event SUBSCR_CONN_E_COMPLETE_LAYER_3 +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_NEW}: state_chg to SUBSCR_CONN_S_AUTH_CIPH +DREF IMSI:901700000004620: MSC conn use - compl_l3 == 0 (0x0: ) +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED + lu_result_sent == 0 +- from HLR, rx _SEND_AUTH_INFO_RESULT; VLR sends Auth Req to MS +<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a800 +DVLR GSUP rx 47: 0a010809710000004026f003222010585df1ae287f6e273dce07090d61320b21042d8b2c3e220861855fb81fc2a800 +DREF VLR subscr IMSI:901700000004620 usage increases to: 2 +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK +DVLR SUBSCR(IMSI:901700000004620) Received 1 auth tuples +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: state_chg to VLR_SUB_AS_WAIT_RESP +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: got auth tuple: use_count=1 key_seq=0 -- will use GSM AKA (is_r99=no, at->vec.auth_types=0x1) +- sending GSM Auth Request for IMSI:901700000004620: tuple use_count=1 key_seq=0 auth_types=0x1 and... +- ...rand=585df1ae287f6e273dce07090d61320b +- ...expecting sres=2d8b2c3e +DREF VLR subscr IMSI:901700000004620 usage decreases to: 1 +<-- GSUP rx OSMO_GSUP_MSGT_SEND_AUTH_INFO_RESULT: vlr_gsupc_read_cb() returns 0 + lu_result_sent == 0 + auth_request_sent == 1 +--- +- MS sends Authen Response, VLR accepts and wants to send Ciphering Mode Command to MS -- but needs Classmark 2 to determine whether A5/3 is supported + MSC <--RAN_GERAN_A-- MS: GSM48_MT_MM_AUTH_RESP +DREF IMSI:901700000004620: MSC conn use + dtap == 1 (0x2: dtap) +DRLL Dispatching 04.08 message GSM48_MT_MM_AUTH_RESP (0x5:0x14) +DMM IMSI:901700000004620: MM GSM AUTHENTICATION RESPONSE (sres = 2d8b2c3e) +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP +DVLR SUBSCR(IMSI:901700000004620) AUTH on GERAN received SRES/RES: 2d8b2c3e (4 bytes) +DVLR SUBSCR(IMSI:901700000004620) AUTH established GSM security context +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_WAIT_RESP}: state_chg to VLR_SUB_AS_AUTHENTICATED +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Removing from parent vlr_lu_fsm(LU:901700000004620) +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Freeing instance +DVLR VLR_Authenticate(LU:901700000004620){VLR_SUB_AS_AUTHENTICATED}: Deallocated +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Received Event VLR_ULA_E_AUTH_RES +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: vlr_loc_upd_post_auth() +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: Set Ciphering Mode +DMM IMSI:901700000004620: to determine whether A5/3 is supported, first ask for a Classmark Update to obtain Classmark 2 + BSC <--BSSAP-BSS-MANAGEMENT-- MSC: CLASSMARK REQ [L3]> 00 01 58 +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_AUTH_CIPH}: state_chg to SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_AUTH}: state_chg to VLR_ULA_S_WAIT_CIPH +DREF IMSI:901700000004620: MSC conn use - dtap == 0 (0x0: ) +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Awaiting results for Auth+Ciph, overruling event SUBSCR_CONN_E_UNUSED + lu_result_sent == 0 +--- +- But the BSSMAP Classmark Update never arrives +- At first, we're still waiting +- Total time passed: 0.000423 s + llist_count(&net->subscr_conns) == 1 + lu_result_sent == 0 +- Total time passed: 1.000658 s + llist_count(&net->subscr_conns) == 1 + lu_result_sent == 0 +- Total time passed: 2.000893 s + llist_count(&net->subscr_conns) == 1 + lu_result_sent == 0 +- Total time passed: 3.001128 s + llist_count(&net->subscr_conns) == 1 + lu_result_sent == 0 +- Total time passed: 4.001363 s + llist_count(&net->subscr_conns) == 1 + lu_result_sent == 0 +- Total time passed: 5.001598 s +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Timeout of T0 +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Received Event SUBSCR_CONN_E_CN_CLOSE +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: Close event, cause: CONGESTION +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_WAIT_CLASSMARK_UPDATE}: state_chg to SUBSCR_CONN_S_RELEASING +DREF IMSI:901700000004620: MSC conn use + release == 1 (0x100: release) +DREF VLR subscr IMSI:901700000004620 usage increases to: 2 +- sending LU Reject for IMSI:901700000004620, cause 22 +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_WAIT_CIPH}: state_chg to VLR_ULA_S_DONE +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_CN_CLOSE +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Event SUBSCR_CONN_E_CN_CLOSE not permitted +DREF VLR subscr IMSI:901700000004620 usage decreases to: 1 +- BSSAP Clear --RAN_GERAN_A--> MS +- SUBSCR_CONN_TIMEOUT has passed, conn is gone. + bssap_clear_sent == 1 +- BSS sends BSSMAP Clear Complete +DREF IMSI:901700000004620: MSC conn use - release == 0 (0x0: ) +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: Received Event SUBSCR_CONN_E_UNUSED +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASING}: state_chg to SUBSCR_CONN_S_RELEASED +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Terminating (cause = OSMO_FSM_TERM_REGULAR) +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Terminating (cause = OSMO_FSM_TERM_PARENT) +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Removing from parent Subscr_Conn(LU:901700000004620) +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: fsm_lu_cleanup called with cause OSMO_FSM_TERM_PARENT +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Freeing instance +DVLR vlr_lu_fsm(LU:901700000004620){VLR_ULA_S_DONE}: Deallocated +DRLL IMSI:901700000004620: Freeing subscriber connection +DREF VLR subscr IMSI:901700000004620 usage decreases to: 0 +DREF freeing VLR subscr IMSI:901700000004620 +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Freeing instance +DMM Subscr_Conn(LU:901700000004620){SUBSCR_CONN_S_RELEASED}: Deallocated + llist_count(&net->subscr_conns) == 0 + lu_result_sent == 2 +===== test_classmark_update_timeout: SUCCESS + +full talloc report on 'msgb' (total 0 bytes in 1 blocks) +talloc_total_blocks(tall_bsc_ctx) == 12 + full talloc report on 'msgb' (total 0 bytes in 1 blocks) talloc_total_blocks(tall_bsc_ctx) == 12 |