Actions
Bug #3991
closedMSC_Tests_Iu.ttcn: Timeout waiting for RESET-ACK after sending RESET
Start date:
05/09/2019
Due date:
% Done:
100%
Resolution:
Spec Reference:
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
Actions
