From 10c914cd4ed6da9841c609faf7950cd45d41d73b Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Tue, 30 Jan 2024 09:50:44 +0100 Subject: [PATCH 1/4] bugfix: if cannot send Msg.2 in RA, cancel RA If we cannot send Msg.2, then basically the RA process is dead (because the UE expects it at a fixed time). Hence, cancel the RA process, so that we do not pick it up again after 1000 frames. --- openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_RA.c | 1 + 1 file changed, 1 insertion(+) diff --git a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_RA.c b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_RA.c index b901810c2e..ca8e2f3e22 100644 --- a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_RA.c +++ b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_RA.c @@ -1254,6 +1254,7 @@ static void nr_generate_Msg2(module_id_t module_idP, if (CCEIndex < 0) { LOG_E(NR_MAC, "%s(): cannot find free CCE for RA RNTI 0x%04x!\n", __func__, ra->rnti); + nr_clear_ra_proc(module_idP, CC_id, frameP, ra); return; } From e2d5758c5db634106400441a8dae8be77836d9ec Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Tue, 30 Jan 2024 09:52:38 +0100 Subject: [PATCH 2/4] MAC: improve log messages, reduce overall verbosity --- openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_RA.c | 17 +++++++++++------ .../NR_MAC_gNB/gNB_scheduler_primitives.c | 3 +-- .../LAYER2/NR_MAC_gNB/gNB_scheduler_ulsch.c | 8 ++++---- openair2/NR_PHY_INTERFACE/NR_IF_Module.c | 2 +- 4 files changed, 17 insertions(+), 13 deletions(-) diff --git a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_RA.c b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_RA.c index ca8e2f3e22..d655fa666b 100644 --- a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_RA.c +++ b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_RA.c @@ -688,7 +688,7 @@ void nr_initiate_ra_proc(module_id_t module_idP, } NR_SCHED_UNLOCK(&nr_mac->sched_lock); - LOG_E(NR_MAC, "[gNB %d][RAPROC] FAILURE: CC_id %d Frame %d initiating RA procedure for preamble index %d\n", module_idP, CC_id, frameP, preamble_index); + LOG_E(NR_MAC, "[gNB %d][RAPROC] FAILURE: CC_id %d %4d.%2d initiating RA procedure for preamble index %d: no free RA process\n", module_idP, CC_id, frameP, slotP, preamble_index); VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_INITIATE_RA_PROC, 0); } @@ -768,8 +768,14 @@ static void nr_generate_Msg3_retransmission(module_id_t module_idP, return; } - LOG_I(NR_MAC, "[gNB %d][RAPROC] Frame %d, Slot %d : CC_id %d Scheduling retransmission of Msg3 in (%d,%d)\n", - module_idP, frame, slot, CC_id, sched_frame, sched_slot); + LOG_I(NR_MAC, + "%4d%2d: RA RNTI %04x CC_id %d Scheduling retransmission of Msg3 in (%d,%d)\n", + frame, + slot, + ra->rnti, + CC_id, + sched_frame, + sched_slot); buffer_index = ul_buffer_index(sched_frame, sched_slot, mu, nr_mac->UL_tti_req_ahead_size); nfapi_nr_ul_tti_request_t *future_ul_tti_req = &nr_mac->UL_tti_req_ahead[CC_id][buffer_index]; @@ -1253,7 +1259,7 @@ static void nr_generate_Msg2(module_id_t module_idP, true); if (CCEIndex < 0) { - LOG_E(NR_MAC, "%s(): cannot find free CCE for RA RNTI 0x%04x!\n", __func__, ra->rnti); + LOG_E(NR_MAC, "cannot find free CCE for Msg2 of RA RNTI 0x%04x!\n", ra->rnti); nr_clear_ra_proc(module_idP, CC_id, frameP, ra); return; } @@ -1456,7 +1462,7 @@ static void nr_generate_Msg2(module_id_t module_idP, } ra->state = WAIT_Msg3; - LOG_W(NR_MAC,"[gNB %d][RAPROC] Frame %d, Subframe %d: rnti %04x RA state %d\n", module_idP, frameP, slotP, ra->rnti, ra->state); + LOG_D(NR_MAC,"[gNB %d][RAPROC] Frame %d, Subframe %d: rnti %04x RA state %d\n", module_idP, frameP, slotP, ra->rnti, ra->state); } } @@ -1699,7 +1705,6 @@ static void nr_generate_Msg4(module_id_t module_idP, // Need to wait until data for Msg4 is ready if (srb_status.bytes_in_buffer == 0) return; - LOG_I(NR_MAC, "(%4d.%2d) SRB%d has %d bytes\n", frameP, slotP, lcid, srb_status.bytes_in_buffer); mac_sdu_length = srb_status.bytes_in_buffer; } diff --git a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_primitives.c b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_primitives.c index 04162b8f37..1bd28321cf 100644 --- a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_primitives.c +++ b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_primitives.c @@ -2376,8 +2376,7 @@ NR_UE_info_t *add_new_nr_ue(gNB_MAC_INST *nr_mac, rnti_t rntiP, NR_CellGroupConf { NR_ServingCellConfigCommon_t *scc = nr_mac->common_channels[0].ServingCellConfigCommon; NR_UEs_t *UE_info = &nr_mac->UE_info; - LOG_I(NR_MAC, "Adding UE with rnti 0x%04x\n", - rntiP); + LOG_I(NR_MAC, "Adding new UE context with RNTI 0x%04x\n", rntiP); dump_nr_list(UE_info->list); // We will attach at the end, to mitigate race conditions diff --git a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_ulsch.c b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_ulsch.c index f1a3e34c85..8fb8abd3fd 100644 --- a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_ulsch.c +++ b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_ulsch.c @@ -377,7 +377,7 @@ static int nr_process_mac_pdu(instance_t module_idP, mac_len = 6; } - LOG_W(MAC, "[RAPROC] Received SDU for CCCH length %d for UE %04x\n", mac_len, UE->rnti); + LOG_D(MAC, "[RAPROC] Received SDU for CCCH length %d for UE %04x\n", mac_len, UE->rnti); prepare_initial_ul_rrc_message(RC.nrmac[module_idP], UE); mac_rlc_data_ind(module_idP, @@ -509,7 +509,7 @@ void handle_nr_ul_harq(const int CC_idP, bool UE_waiting_CFRA_msg3 = get_UE_waiting_CFRA_msg3(nrmac, CC_idP, frame, slot); if (!UE || UE_waiting_CFRA_msg3 == true) { - LOG_W(NR_MAC, "handle harq for rnti %04x, in RA process\n", crc_pdu->rnti); + LOG_D(NR_MAC, "handle harq for rnti %04x, in RA process\n", crc_pdu->rnti); for (int i = 0; i < NR_NB_RA_PROC_MAX; ++i) { NR_RA_t *ra = &nrmac->common_channels[CC_idP].ra[i]; if (ra->state >= WAIT_Msg3 && ra->rnti == crc_pdu->rnti) { @@ -518,7 +518,7 @@ void handle_nr_ul_harq(const int CC_idP, } } NR_SCHED_UNLOCK(&nrmac->sched_lock); - LOG_E(NR_MAC, "%s(): unknown RNTI 0x%04x in PUSCH\n", __func__, crc_pdu->rnti); + LOG_E(NR_MAC, "no RA proc for RNTI 0x%04x in Msg3/PUSCH\n", crc_pdu->rnti); return; } NR_UE_sched_ctrl_t *sched_ctrl = &UE->UE_sched_ctrl; @@ -792,7 +792,7 @@ static void _nr_rx_sdu(const module_id_t gnb_mod_idP, // Let's abort the current RA, so the UE will trigger a new RA later but using RRCSetupRequest instead. A better solution may be implemented mac_remove_nr_ue(gNB_mac, ra->rnti); nr_clear_ra_proc(gnb_mod_idP, CC_idP, frameP, ra); - LOG_W(NR_MAC, "No UE found with C-RNTI %04x, ignoring Msg.3 to have UE come back with new RA attempt\n", ra->rnti); + LOG_W(NR_MAC, "No UE found with C-RNTI %04x, ignoring Msg3 to have UE come back with new RA attempt\n", ra->rnti); return; } else { // Reset Msg4_ACKed to not schedule ULSCH and DLSCH before RRC Reconfiguration diff --git a/openair2/NR_PHY_INTERFACE/NR_IF_Module.c b/openair2/NR_PHY_INTERFACE/NR_IF_Module.c index 117b028c9a..4f23c327a7 100644 --- a/openair2/NR_PHY_INTERFACE/NR_IF_Module.c +++ b/openair2/NR_PHY_INTERFACE/NR_IF_Module.c @@ -77,7 +77,7 @@ void handle_nr_rach(NR_UL_IND_t *UL_info) bool in_timewindow = frame_diff == 0 || (frame_diff == 1 && UL_info->slot < 7); if (UL_info->rach_ind.number_of_pdus > 0 && in_timewindow) { - LOG_A(MAC,"UL_info[Frame %d, Slot %d] Calling initiate_ra_proc RACH:SFN/SLOT:%d/%d\n", + LOG_D(MAC,"UL_info[Frame %d, Slot %d] Calling initiate_ra_proc RACH:SFN/SLOT:%d/%d\n", UL_info->frame, UL_info->slot, UL_info->rach_ind.sfn, UL_info->rach_ind.slot); for (int i = 0; i < UL_info->rach_ind.number_of_pdus; i++) { UL_info->rach_ind.number_of_pdus--; From 2e7d95746f2d259c3090d877e3c358cc9d8113d6 Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Tue, 30 Jan 2024 09:53:11 +0100 Subject: [PATCH 3/4] RRC: demote various log levels --- openair2/RRC/NR/rrc_gNB.c | 7 ++----- openair2/RRC/NR/rrc_gNB_NGAP.c | 17 ++++++----------- openair2/RRC/NR/rrc_gNB_UE_context.c | 2 +- 3 files changed, 9 insertions(+), 17 deletions(-) diff --git a/openair2/RRC/NR/rrc_gNB.c b/openair2/RRC/NR/rrc_gNB.c index 7c3c200f15..46a535e232 100644 --- a/openair2/RRC/NR/rrc_gNB.c +++ b/openair2/RRC/NR/rrc_gNB.c @@ -523,8 +523,7 @@ static void rrc_gNB_generate_RRCReject(module_id_t module_id, rrc_gNB_ue_context static void rrc_gNB_process_RRCSetupComplete(const protocol_ctxt_t *const ctxt_pP, rrc_gNB_ue_context_t *ue_context_pP, NR_RRCSetupComplete_IEs_t *rrcSetupComplete) //----------------------------------------------------------------------------- { - LOG_A(NR_RRC, PROTOCOL_NR_RRC_CTXT_UE_FMT" [RAPROC] Logical Channel UL-DCCH, " "processing NR_RRCSetupComplete from UE (SRB1 Active)\n", - PROTOCOL_NR_RRC_CTXT_UE_ARGS(ctxt_pP)); + LOG_A(NR_RRC, "UE %d Processing NR_RRCSetupComplete from UE\n", ue_context_pP->ue_context.rrc_ue_id); ue_context_pP->ue_context.Srb[1].Active = 1; ue_context_pP->ue_context.Srb[2].Active = 0; ue_context_pP->ue_context.StatusRrc = NR_RRC_CONNECTED; @@ -1091,9 +1090,7 @@ static void rrc_gNB_process_RRCReestablishmentComplete(const protocol_ctxt_t *co const uint8_t xid) { gNB_RRC_UE_t *ue_p = &ue_context_pP->ue_context; - LOG_I(NR_RRC, - "[RAPROC] UE %04x Logical Channel UL-DCCH, processing NR_RRCReestablishmentComplete from UE (SRB1 Active)\n", - ue_p->rnti); + LOG_I(NR_RRC, "UE %d Processing NR_RRCReestablishmentComplete from UE\n", ue_p->rrc_ue_id); int i = 0; diff --git a/openair2/RRC/NR/rrc_gNB_NGAP.c b/openair2/RRC/NR/rrc_gNB_NGAP.c index 05067fe12f..e3db2bbb7a 100644 --- a/openair2/RRC/NR/rrc_gNB_NGAP.c +++ b/openair2/RRC/NR/rrc_gNB_NGAP.c @@ -145,11 +145,6 @@ nr_rrc_pdcp_config_security( nr_derive_key(RRC_ENC_ALG, UE->ciphering_algorithm, UE->kgnb, kRRCenc); nr_derive_key(RRC_INT_ALG, UE->integrity_algorithm, UE->kgnb, kRRCint); - if (!IS_SOFTMODEM_IQPLAYER) { - SET_LOG_DUMP(DEBUG_SECURITY) ; - } - - if ( LOG_DUMPFLAG( DEBUG_SECURITY ) ) { if (print_keys == 1 ) { print_keys =0; @@ -511,7 +506,7 @@ static NR_CipheringAlgorithm_t rrc_gNB_select_ciphering( } } - LOG_I(RRC, "selecting ciphering algorithm %d\n", ret); + LOG_D(RRC, "selecting ciphering algorithm %d\n", ret); return ret; } @@ -547,7 +542,7 @@ static e_NR_IntegrityProtAlgorithm rrc_gNB_select_integrity( } } - LOG_I(RRC, "selecting integrity algorithm %d\n", ret); + LOG_D(RRC, "selecting integrity algorithm %d\n", ret); return ret; } @@ -585,13 +580,13 @@ static int rrc_gNB_process_security(const protocol_ctxt_t *const ctxt_pP, rrc_gN } LOG_I(NR_RRC, - "[gNB %d][UE %x] Selected security algorithms (%p): %lx, %x, %s\n", + "[gNB %d][UE %d] Selected security algorithms (%p): ciphering %lx, integrity %x (algorithms %s)\n", ctxt_pP->module_id, - UE->rnti, + UE->rrc_ue_id, security_capabilities_pP, - (unsigned long)cipheringAlgorithm, + cipheringAlgorithm, integrityProtAlgorithm, - changed ? "changed" : "same"); + changed ? "changed" : "are the same"); return changed; } diff --git a/openair2/RRC/NR/rrc_gNB_UE_context.c b/openair2/RRC/NR/rrc_gNB_UE_context.c index db082c1965..6c61887158 100644 --- a/openair2/RRC/NR/rrc_gNB_UE_context.c +++ b/openair2/RRC/NR/rrc_gNB_UE_context.c @@ -72,7 +72,7 @@ rrc_gNB_ue_context_t *rrc_gNB_allocate_new_ue_context(gNB_RRC_INST *rrc_instance for(int i = 0; i < NB_RB_MAX; i++) new_p->ue_context.pduSession[i].xid = -1; - LOG_I(NR_RRC, "Returning new RRC UE context RRC ue id: %d\n", new_p->ue_context.rrc_ue_id); + LOG_D(NR_RRC, "Returning new RRC UE context RRC ue id: %d\n", new_p->ue_context.rrc_ue_id); return(new_p); } From e59648e17fe3a64a6fdc0330e0791e3f2eda51d5 Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Tue, 30 Jan 2024 09:53:32 +0100 Subject: [PATCH 4/4] NGAP: demote some logs to debug, improve others --- openair3/NGAP/ngap_common.h | 4 ++-- openair3/NGAP/ngap_gNB_handlers.c | 2 +- openair3/NGAP/ngap_gNB_nas_procedures.c | 14 +++++++------- 3 files changed, 10 insertions(+), 10 deletions(-) diff --git a/openair3/NGAP/ngap_common.h b/openair3/NGAP/ngap_common.h index 4b845690c6..3c060eac03 100644 --- a/openair3/NGAP/ngap_common.h +++ b/openair3/NGAP/ngap_common.h @@ -102,7 +102,7 @@ extern int asn1_xer_print; # define NGAP_WARN(x, args...) LOG_W(NGAP, x, ##args) # define NGAP_TRAF(x, args...) LOG_I(NGAP, x, ##args) # define NGAP_INFO(x, args...) LOG_I(NGAP, x, ##args) -# define NGAP_DEBUG(x, args...) LOG_I(NGAP, x, ##args) +# define NGAP_DEBUG(x, args...) LOG_D(NGAP, x, ##args) #define NGAP_FIND_PROTOCOLIE_BY_ID(IE_TYPE, ie, container, IE_ID, mandatory) \ do { \ @@ -118,7 +118,7 @@ extern int asn1_xer_print; if (mandatory) { \ AssertFatal(NGAP, "NGAP_FIND_PROTOCOLIE_BY_ID ie is NULL (searching for ie: %ld)\n", IE_ID); \ } else { \ - NGAP_INFO("NGAP_FIND_PROTOCOLIE_BY_ID ie is NULL (searching for ie: %ld)\n", IE_ID); \ + NGAP_DEBUG("NGAP_FIND_PROTOCOLIE_BY_ID ie is NULL (searching for ie: %ld)\n", IE_ID); \ } \ } \ } while (0); \ diff --git a/openair3/NGAP/ngap_gNB_handlers.c b/openair3/NGAP/ngap_gNB_handlers.c index 0fb9fd0dbc..4df67c2e34 100644 --- a/openair3/NGAP/ngap_gNB_handlers.c +++ b/openair3/NGAP/ngap_gNB_handlers.c @@ -775,7 +775,7 @@ static int ngap_gNB_handle_initial_context_request(sctp_assoc_t assoc_id, uint32 AssertFatal(ie, "AllowedNSSAI not present, forging 2 NSSAI\n"); - NGAP_INFO("AllowedNSSAI.list.count %d\n", ie->value.choice.AllowedNSSAI.list.count); + NGAP_DEBUG("AllowedNSSAI.list.count %d\n", ie->value.choice.AllowedNSSAI.list.count); msg->nb_allowed_nssais = ie->value.choice.AllowedNSSAI.list.count; for(i = 0; i < ie->value.choice.AllowedNSSAI.list.count; i++) { diff --git a/openair3/NGAP/ngap_gNB_nas_procedures.c b/openair3/NGAP/ngap_gNB_nas_procedures.c index 6d67920bcb..ffa3bf869e 100644 --- a/openair3/NGAP/ngap_gNB_nas_procedures.c +++ b/openair3/NGAP/ngap_gNB_nas_procedures.c @@ -95,8 +95,8 @@ int ngap_gNB_handle_nas_first_req(instance_t instance, ngap_nas_first_req_t *UEf amf_desc_p = ngap_gNB_nnsf_select_amf_by_guami(instance_p, UEfirstReq->establishment_cause, UEfirstReq->ue_identity.guami); if (amf_desc_p) { - NGAP_INFO("[gNB %ld] Chose AMF '%s' (assoc_id %d) through GUAMI MCC %d MNC %d AMFRI %d AMFSI %d AMFPT %d\n", - instance, + NGAP_INFO("UE %d: Chose AMF '%s' (assoc_id %d) through GUAMI MCC %d MNC %d AMFRI %d AMFSI %d AMFPT %d\n", + UEfirstReq->gNB_ue_ngap_id, amf_desc_p->amf_name, amf_desc_p->assoc_id, UEfirstReq->ue_identity.guami.mcc, @@ -115,8 +115,8 @@ int ngap_gNB_handle_nas_first_req(instance_t instance, ngap_nas_first_req_t *UEf if (amf_desc_p) { NGAP_INFO( - "[gNB %ld] Chose AMF '%s' (assoc_id %d) through S-TMSI AMFSI %d and selected PLMN Identity index %d MCC %d MNC %d\n", - instance, + "UE %d: Chose AMF '%s' (assoc_id %d) through S-TMSI AMFSI %d and selected PLMN Identity index %d MCC %d MNC %d\n", + UEfirstReq->gNB_ue_ngap_id, amf_desc_p->amf_name, amf_desc_p->assoc_id, UEfirstReq->ue_identity.s_tmsi.amf_set_id, @@ -134,8 +134,8 @@ int ngap_gNB_handle_nas_first_req(instance_t instance, ngap_nas_first_req_t *UEf amf_desc_p = ngap_gNB_nnsf_select_amf_by_plmn_id(instance_p, UEfirstReq->establishment_cause, UEfirstReq->selected_plmn_identity); if (amf_desc_p) { - NGAP_INFO("[gNB %ld] Chose AMF '%s' (assoc_id %d) through selected PLMN Identity index %d MCC %d MNC %d\n", - instance, + NGAP_INFO("UE %d: Chose AMF '%s' (assoc_id %d) through selected PLMN Identity index %d MCC %d MNC %d\n", + UEfirstReq->gNB_ue_ngap_id, amf_desc_p->amf_name, amf_desc_p->assoc_id, UEfirstReq->selected_plmn_identity, @@ -153,7 +153,7 @@ int ngap_gNB_handle_nas_first_req(instance_t instance, ngap_nas_first_req_t *UEf amf_desc_p = ngap_gNB_nnsf_select_amf(instance_p, UEfirstReq->establishment_cause); if (amf_desc_p) { - NGAP_INFO("[gNB %ld] Chose AMF '%s' (assoc_id %d) through highest relative capacity\n", instance, amf_desc_p->amf_name, amf_desc_p->assoc_id); + NGAP_INFO("UE %d: Chose AMF '%s' (assoc_id %d) through highest relative capacity\n", UEfirstReq->gNB_ue_ngap_id, amf_desc_p->amf_name, amf_desc_p->assoc_id); } }