Merge remote-tracking branch 'origin/fix-ra-reduce-logs' into integration_2024_w05

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,8 @@ 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;
     }
 
@@ -1455,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);
   }
 }
 
@@ -1698,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_D(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;
     }
 

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

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;
@@ -794,7 +794,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

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--;

openair2/RRC/NR/rrc_gNB.c

@@ -493,8 +493,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;
@@ -946,9 +945,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;
 

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;
@@ -590,7 +585,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;
 }
@@ -626,7 +621,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;
 }
@@ -664,13 +659,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;
 }
 

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);
 }
 

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);                                                                                                                          \

openair3/NGAP/ngap_gNB_handlers.c

@@ -785,7 +785,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++) {

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);
     }
   }