Project

General

Profile

Actions
Copy link

Bug #3991

closed

MSC_Tests_Iu.ttcn: Timeout waiting for RESET-ACK after sending RESET

Added by laforge almost 5 years ago. Updated almost 5 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
pespin
Category:
IuCS support
Target version:
-
Start date:
05/09/2019
Due date:
% Done:

100%

Resolution:
Spec Reference:
Tags:
3G

Description

I've been looking into the MSC_Tests.TC_iu_emerg_call_imsi.merged failure, and it seems a genuine bug that this test is detecting.

  • the UE performs a sucessful LU / IMSI attach
  • the UE sends a CM SERVICE REQUEST (emergency)
  • the CN decides to authenticate it (a valid design choice for an emergency call from a known subscriber)
  • the CN then releases the Iu connection after CommonID instead of proceeding with the call ?!?

th relevant portion of the MSC log is below. TTCN3 and pcap files attached.

Thu May  9 04:57:07 2019 DIUCS <000f> sccp_ran.c:84 (UTRAN-Iu-165 from RI=SSN_PC,PC=0.24.3,SSN=RANAP) sccp_ran_sap_up(N-CONNECT.indication)
Thu May  9 04:57:07 2019 DIUCS <000f> ran_msg_iu.c:260 msc_a(unknown:UTRAN-Iu-165:NONE)[0x555555971410]{MSC_A_ST_VALIDATE_L3}: RAN decode: RANAP: dir=1 proc=19
Thu May  9 04:57:07 2019 DIUCS <000f> msc_a.c:1489 msc_a(unknown:UTRAN-Iu-165:NONE)[0x555555971410]{MSC_A_ST_VALIDATE_L3}: RAN decode: RANAP InitialUE RAN PDU
Thu May  9 04:57:07 2019 DMM <0002> gsm_04_08.c:738 msc_a(TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_VALIDATE_L3}: Rx CM SERVICE REQUEST cm_service_type=Emergency-Call
Thu May  9 04:57:07 2019 DVLR <000e> fsm.c:423 Process_Access_Request_VLR(TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_INIT}: Allocated
Thu May  9 04:57:07 2019 DVLR <000e> fsm.c:453 Process_Access_Request_VLR(TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_INIT}: is child of msc_a(TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:675 Process_Access_Request_VLR(TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_INIT}: rev=R99 net=UTRAN Auth+Ciph
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:699 Process_Access_Request_VLR(TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_INIT}: Received Event PR_ARQ_E_START
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:333 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_INIT}: proc_arq_vlr_fn_post_imsi()
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:340 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_INIT}: State change to PR_ARQ_S_WAIT_AUTH (no timeout)
Thu May  9 04:57:07 2019 DVLR <000e> fsm.c:423 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_NEEDS_AUTH}: Allocated
Thu May  9 04:57:07 2019 DVLR <000e> fsm.c:453 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_NEEDS_AUTH}: is child of Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]
Thu May  9 04:57:07 2019 DVLR <000e> vlr_auth_fsm.c:628 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_NEEDS_AUTH}: Received Event VLR_AUTH_E_START
Thu May  9 04:57:07 2019 DVLR <000e> vlr_auth_fsm.c:318 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_NEEDS_AUTH}: State change to VLR_SUB_AS_NEEDS_AUTH_WAIT_AI (T0, 30s)
Thu May  9 04:57:07 2019 DVLR <000e> vlr.c:752 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: Received Event VLR_AUTH_E_HLR_SAI_ACK
Thu May  9 04:57:07 2019 DVLR <000e> vlr.c:732 SUBSCR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29) Received 1 auth tuples
Thu May  9 04:57:07 2019 DVLR <000e> vlr_auth_fsm.c:374 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_NEEDS_AUTH_WAIT_AI}: State change to VLR_SUB_AS_WAIT_RESP (no timeout)
Thu May  9 04:57:07 2019 DVLR <000e> vlr_auth_fsm.c:286 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{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)
Thu May  9 04:57:07 2019 DMM <0002> gsm_04_08.c:615 Tx AUTH REQ (rand = baf7ecb2f415c5be01a01799ac82fa99)
Thu May  9 04:57:07 2019 DMM <0002> gsm_04_08.c:617    AUTH REQ (autn = 7018072917c30dc5e5cbf8ea314b469c)
Thu May  9 04:57:07 2019 DIUCS <000f> ran_msg_iu.c:387 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_AUTH_CIPH}: RAN encode: RANAP: DTAP
Thu May  9 04:57:07 2019 DIUCS <000f> sccp_ran.c:108 (UTRAN-Iu-165) sccp_ran_sap_up(N-DATA.indication)
Thu May  9 04:57:07 2019 DIUCS <000f> ran_msg_iu.c:260 msc_i(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x5555559a7750]{READY}: RAN decode: RANAP: dir=1 proc=20
Thu May  9 04:57:07 2019 DIUCS <000f> ran_msg_iu.c:260 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_AUTH_CIPH}: RAN decode: RANAP: dir=1 proc=20
Thu May  9 04:57:07 2019 DIUCS <000f> msc_a.c:1489 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_AUTH_CIPH}: RAN decode: RANAP DirectTransfer RAN PDU
Thu May  9 04:57:07 2019 DMM <0002> gsm_04_08.c:977 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_AUTH_CIPH}: MM UMTS AUTHENTICATION RESPONSE (res = 0ccbefe57088f5c6)
Thu May  9 04:57:07 2019 DVLR <000e> vlr.c:1323 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_WAIT_RESP}: Received Event VLR_AUTH_E_MS_AUTH_RESP
Thu May  9 04:57:07 2019 DVLR <000e> vlr_auth_fsm.c:136 SUBSCR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29) AUTH on UTRAN received RES: 0ccbefe57088f5c6 (8 bytes)
Thu May  9 04:57:07 2019 DVLR <000e> vlr_auth_fsm.c:195 SUBSCR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29) AUTH established UMTS security context
Thu May  9 04:57:07 2019 DVLR <000e> vlr_auth_fsm.c:244 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_WAIT_RESP}: Authentication terminating with result PASSED
Thu May  9 04:57:07 2019 DVLR <000e> vlr_auth_fsm.c:248 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_WAIT_RESP}: State change to VLR_SUB_AS_AUTHENTICATED (no timeout)
Thu May  9 04:57:07 2019 DVLR <000e> vlr_auth_fsm.c:253 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_AUTHENTICATED}: Terminating (cause = OSMO_FSM_TERM_REGULAR)
Thu May  9 04:57:07 2019 DVLR <000e> vlr_auth_fsm.c:253 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_AUTHENTICATED}: Removing from parent Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]
Thu May  9 04:57:07 2019 DVLR <000e> vlr_auth_fsm.c:253 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_AUTH}: Received Event PR_ARQ_E_AUTH_RES
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:284 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_AUTH}: _proc_arq_vlr_node2()
Thu May  9 04:57:07 2019 DVLR <000e> vlr.c:1357 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_AUTH}: Set Ciphering Mode
Thu May  9 04:57:07 2019 DIUCS <000f> ran_msg_iu.c:387 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_AUTH_CIPH}: RAN encode: RANAP: CIPHER_MODE_COMMAND
Thu May  9 04:57:07 2019 DIUCS <000f> ran_msg_iu.c:369 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_AUTH_CIPH}: RAN encode: RANAP: Tx RANAP SECURITY MODE COMMAND to RNC, ik 6bc085046b44594752fbc1cd94d597e6
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:315 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_AUTH}: State change to PR_ARQ_S_WAIT_CIPH (no timeout)
Thu May  9 04:57:07 2019 DVLR <000e> fsm.c:535 VLR_Authenticate(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596ce20]{VLR_SUB_AS_AUTHENTICATED}: Deallocated
Thu May  9 04:57:07 2019 DIUCS <000f> sccp_ran.c:108 (UTRAN-Iu-165) sccp_ran_sap_up(N-DATA.indication)
Thu May  9 04:57:07 2019 DIUCS <000f> ran_msg_iu.c:260 msc_i(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x5555559a7750]{READY}: RAN decode: RANAP: dir=2 proc=6
Thu May  9 04:57:07 2019 DIUCS <000f> ran_msg_iu.c:260 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_AUTH_CIPH}: RAN decode: RANAP: dir=2 proc=6
Thu May  9 04:57:07 2019 DIUCS <000f> msc_a.c:1489 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_AUTH_CIPH}: RAN decode: RANAP SecurityModeControl successfulOutcome
Thu May  9 04:57:07 2019 DVLR <000e> vlr.c:1335 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_CIPH}: Received Event PR_ARQ_E_CIPH_RES
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:250 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_ciph()
Thu May  9 04:57:07 2019 DIUCS <000f> ran_msg_iu.c:387 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_AUTH_CIPH}: RAN encode: RANAP: COMMON_ID
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:222 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_node2_post_vlr()
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:207 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_pres()
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:191 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_trace()
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:169 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_CIPH}: _proc_arq_vlr_post_imei()
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:182 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_CIPH}: proc_arq_fsm_done(PASSED)
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:103 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_WAIT_CIPH}: State change to PR_ARQ_S_DONE (no timeout)
Thu May  9 04:57:07 2019 DVLR <000e> vlr_access_req_fsm.c:112 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_DONE}: Process Access Request result: PASSED
Thu May  9 04:57:07 2019 DSMPP <000c> smpp_smsc.c:656 [msc_tester] Tx ALERT_NOTIFICATION (491230001018/3/1): Available
Thu May  9 04:57:12 2019 DIUCS <000f> msc_a.c:697 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_RELEASING}: Releasing: msc_a use is 1 (cm_service_cc)
Thu May  9 04:57:12 2019 DIUCS <000f> msc_a.c:721 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_RELEASING}: Releasing: canceling still pending use: cm_service_cc (1)
Thu May  9 04:57:12 2019 DIUCS <000f> ran_msg_iu.c:387 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_RELEASING}: RAN encode: RANAP: CLEAR_COMMAND
Thu May  9 04:57:42 2019 DIUCS <000f> msc_a.c:672 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_RELEASING}: Timeout while releasing, discarding right now
Thu May  9 04:57:42 2019 DIUCS <000f> msc_a.c:779 msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]{MSC_A_ST_RELEASED}: Released: msc_a use is 0 (-)
Thu May  9 04:57:42 2019 DVLR <000e> msc_a.c:781 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_DONE}: Terminating in cascade, depth 2 (cause = OSMO_FSM_TERM_PARENT, caused by: msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410])
Thu May  9 04:57:42 2019 DVLR <000e> msc_a.c:781 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_DONE}: Removing from parent msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]
Thu May  9 04:57:42 2019 DVLR <000e> fsm.c:514 Process_Access_Request_VLR(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x55555596f4a0]{PR_ARQ_S_DONE}: Deferring: will deallocate with msc_a(IMSI-262420000001018:MSISDN-491230001018:TMSI-0x1CC30D29:UTRAN-Iu-165:CM_SERVICE_REQ)[0x555555971410]
Thu May  9 04:57:42 2019 DIUCS <000f> ran_conn.c:142 ran_peer(UTRAN-Iu:RI-SSN_PC:PC-0-24-3:SSN-RANAP)[0x55555596a950]{READY}: Closing UTRAN-Iu-165

Files

MSC_Tests.TC_iu_emerg_call_imsi.merged MSC_Tests.TC_iu_emerg_call_imsi.merged 296 KB laforge, 05/09/2019 09:48 AM
MSC_Tests_Iu.TC_iu_emerg_call_imsi.pcap MSC_Tests_Iu.TC_iu_emerg_call_imsi.pcap 27.9 KB laforge, 05/09/2019 09:48 AM
Actions
Copy link
 #1

Updated by laforge almost 5 years ago

note: TC_iu_lu_imsi_reject also seems to fail in a similar way: There's never any CM SERVICE ACCEPT after the SecurityModeComplete + CommonID procedure.

Actions
Copy link
 #2

Updated by laforge almost 5 years ago

  • Subject changed from emergency call over Iu failing (TC_iu_emerg_call_imsi.merged) to IuCS never sends CM SERVICE ACCEPT

Same in TC_iu_lu_and_mo_sms

So the general problem seems to be that the CM SERVICE ACCEPT is not sent to the UE, resulting in a 5s timeout after the CommonID closing down the Iu connection.

Actions
Copy link
 #3

Updated by osmith almost 5 years ago

  • Status changed from New to In Progress
  • Assignee changed from 4368 to osmith
Actions
Copy link
 #4

Updated by osmith almost 5 years ago

  • % Done changed from 0 to 20

I found the reason why it doesn't send it: par->implicitly_accepted_parq_by_ciphering_cmd is 1 here:

https://git.osmocom.org/osmo-msc/tree/src/libvlr/vlr_access_req_fsm.c?id=b683dcfe6bda723413b19c3bf5789d1a3bc3f7c7#n124

I've asked in the chat about that variable, and laforge wrote:

osmith: the CM SERVICE REQ is implicitly accepted by some messages, this should be described in 04.08 or its successor
osmith: see 3GPP TS 24.008 Section 4.5.1.1
In Iu mode, the MS shall consider the MM connection establishment to be completed when - receiving an indication from the RR sublayer that the security mode control procedure is completed in MM sublayer state WAIT FOR OUTGOING MM CONNECTION; or receiving a CM SERVICE ACCEPT message.
osmith: so ideally we'd have some kind of flag in the test suite logic by which the configuration (per test case? global?) can decide if we expect an implicit or an explicit cm service accept

I'm looking into adding such a flag now.

Actions
Copy link
 #5

Updated by osmith almost 5 years ago

  • Subject changed from IuCS never sends CM SERVICE ACCEPT to MSC_Tests_Iu.ttcn: Timeout waiting for RESET-ACK after sending RESET
  • Assignee changed from osmith to 4368

From what I can tell, CM SERVICE ACCEPT is not the issue. The implicit CM SERVICE ACCEPT is expected in the spec, in OsmoMSC and also in the testsuite code. In BSC_ConnectionHandler.ttcn, we have:

    /* Send BSSAP_Conn_Req with COMPL L3 INFO to MSC */
    f_cl3_or_initial_ue(l3_info);

    f_mm_common();
    if (g_pars.net.expect_ciph) {
        /* implicit CM SERVICE ACCEPT? */
    } else {
        if (etype != EST_TYPE_PAG_RESP) {
            /* explicit CM SERVICE ACCEPT */
            BSSAP.receive(tr_PDU_DTAP_MT(tr_CM_SERV_ACC));
        }
    }

So there is already a flag for CM SERVICE ACCEPT: g_pars.net.expect_ciph

The way the tests are structured, the expect_ciph flag is already set as desired in the 2g test code, and the 3g test code calls the same functions. I was wondering if the 3g test code changed this flag, and for a while I thought this was the case, in f_init_pars() (see the if (not ran_is_geran) part). But I had confused expect_auth with expect_ciph; expect_ciph is the same in 2g and 3g.

To make sure that CM SERVICE ACCEPT is unrelated, I have commented out the whole if...else block in the above code snippet, to make it always expect an implicit CM SERVICE ACCEPT, even if expect_ciph was set to the wrong value. I ran the test again, and it had the same result, as without this change:

Timeout waiting for RESET-ACK after sending RESET
      MSC_Tests_Iu.ttcn:422 MSC_Tests_Iu control part
      MSC_Tests_Iu.ttcn:185 TC_iu_emerg_call_imsi testcase

In total, we have 25 Iu tests that fail with the same error:

TC_iu_lu_imsi_reject, TC_iu_lu_imsi_timeout_gsup, TC_iu_cmserv_imsi_unknown, TC_iu_lu_and_mo_call, TC_iu_lu_auth_sai_timeout, TC_iu_lu_by_imei, TC_iu_emerg_call_imsi, TC_iu_establish_and_nothing, TC_iu_mo_setup_and_nothing, TC_iu_mo_crcx_ran_timeout, TC_iu_mo_crcx_ran_reject, TC_iu_gsup_cancel, TC_iu_mo_release_timeout, TC_iu_lu_and_mo_sms, TC_iu_lu_and_mt_sms_paging_and_nothing, TC_iu_smpp_mo_sms, TC_iu_gsup_mo_sms, TC_iu_gsup_mo_smma, TC_iu_gsup_mo_mt_sms_rp_mr, TC_iu_lu_and_mo_ussd_single_request, TC_iu_lu_and_mo_ussd_during_mt_call, TC_iu_lu_and_mt_ussd_during_mt_call, TC_iu_lu_and_ss_session_timeout, TC_iu_lu_with_invalid_mcc_mnc, TC_mo_cc_iu_release

I did not expect this issue to take up as much time as it did, and with CM SERVICE ACCEPT ruled out, it feels like we're at the start again. I also need to work on other issues and I'm away on Thursday and Friday, so I'm unassigning this one.

Actions
Copy link
 #6

Updated by pespin almost 5 years ago

  • Assignee changed from 4368 to pespin
Actions
Copy link
 #7

Updated by pespin almost 5 years ago

  • % Done changed from 20 to 50

The RESET-ACK after sending RESET issue is fixed by osmo-ttcn3-hacks 3dd33bc8f6d7adfa407ab05a768c3278bfa5c00c. It's already merged since a few days ago (Friday).

There's still other issues for IU. The one related to CM SERVICE ACCEPT I think should be fixed by: https://gerrit.osmocom.org/c/osmo-ttcn3-hacks/+/14354

However, TC_iu_lu_and_mo_call still fails after that patch, but it fails for different reason and way afterwards.

Actions
Copy link
 #8

Updated by pespin almost 5 years ago

  • Status changed from In Progress to Feedback
  • % Done changed from 50 to 90

Other failure seems related to some parts for Iu not yet implemented in BSC_ConnectionHandler.ttcn (handling RAB_assignmentRequest and alike). I'll create a new ticket to handle that since it's not really a related fix.

Setting this ticket as feedback to see in next days whether some tests are happy with the fix proposed above.

Actions
Copy link
 #9

Updated by pespin almost 5 years ago

  • Status changed from Feedback to Resolved
  • % Done changed from 90 to 100

Some tests were fixed, and other ones fail due to implementation missing as described in last comment. Closing this ticket.

Actions
Copy link

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)