maki/openairinterface5g
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge remote-tracking branch 'origin/logs-refactor-orange' into integration_2024_w44 (!3078)

Browse Source 
Simplify logs in gNB&UE

- reduce the amount of printf() that outputs useless info
- in MAC, PHY, NGAP, RRC, mark some "important" UE events with LOG_A for
  better visibility -> can put log_config.global_log_level analysis to
  only see important stuff
- in RRC, use some macro to consistently print logs
- track the cellID of a UE in RRC
This commit is contained in:
Robert Schmidt
2024-11-01 11:58:47 +01:00
parent 25405d1720 f00ee9af2f
commit da7a028a3f
30 changed files with 169 additions and 237 deletions
Download Patch File Download Diff File Expand all files Collapse all files
openair2/RRC/NR/nr_rrc_config.c
+2 -1
View File
@@ -1990,7 +1990,8 @@ NR_MeasurementTimingConfiguration_t *get_new_MeasurementTimingConfiguration(cons
int encode_MeasurementTimingConfiguration(const struct NR_MeasurementTimingConfiguration *mtc, uint8_t *buf, int buf_len)
{
DevAssert(mtc != NULL);
xer_fprint(stdout, &asn_DEF_NR_MeasurementTimingConfiguration, mtc);
if (LOG_DEBUGFLAG(DEBUG_ASN1))
xer_fprint(stdout, &asn_DEF_NR_MeasurementTimingConfiguration, mtc);
asn_enc_rval_t enc_rval = uper_encode_to_buffer(&asn_DEF_NR_MeasurementTimingConfiguration, NULL, mtc, buf, buf_len);
AssertFatal(enc_rval.encoded > 0, "ASN1 message encoding failed (%s, %lu)!\n", enc_rval.failed_type->name, enc_rval.encoded);
return (enc_rval.encoded + 7) / 8;
openair2/RRC/NR/nr_rrc_defs.h
+8 -6
View File
@@ -69,12 +69,6 @@
#include "intertask_interface.h"
#define PROTOCOL_NR_RRC_CTXT_UE_FMT PROTOCOL_CTXT_FMT
#define PROTOCOL_NR_RRC_CTXT_UE_ARGS(CTXT_Pp) PROTOCOL_NR_CTXT_ARGS(CTXT_Pp)
#define PROTOCOL_NR_RRC_CTXT_FMT PROTOCOL_CTXT_FMT
#define PROTOCOL_NR_RRC_CTXT_ARGS(CTXT_Pp) PROTOCOL_NR_CTXT_ARGS(CTXT_Pp)
// 3GPP TS 38.331 Section 12 Table 12.1-1: UE performance requirements for RRC procedures for UEs
#define NR_RRC_SETUP_DELAY_MS 10
#define NR_RRC_RECONFIGURATION_DELAY_MS 10
@@ -243,6 +237,7 @@ typedef struct gNB_RRC_UE_s {
uint64_t ng_5G_S_TMSI_Part1;
NR_EstablishmentCause_t establishment_cause;
uint64_t nr_cellid;
uint32_t rrc_ue_id;
uint64_t amf_ue_ngap_id;
nr_rrc_guami_t ue_guami;
@@ -426,6 +421,13 @@ typedef struct gNB_RRC_INST_s {
} gNB_RRC_INST;
#define UE_LOG_FMT "(cellID %lx, UE ID %d RNTI %04x)"
#define UE_LOG_ARGS(ue_context) (ue_context)->nr_cellid, (ue_context)->rrc_ue_id, (ue_context)->rnti
#define LOG_UE_DL_EVENT(ue_context, fmt, ...) LOG_A(NR_RRC, "[DL] " UE_LOG_FMT " " fmt, UE_LOG_ARGS(ue_context) __VA_OPT__(,) __VA_ARGS__)
#define LOG_UE_EVENT(ue_context, fmt, ...) LOG_A(NR_RRC, "[--] " UE_LOG_FMT " " fmt, UE_LOG_ARGS(ue_context) __VA_OPT__(,) __VA_ARGS__)
#define LOG_UE_UL_EVENT(ue_context, fmt, ...) LOG_A(NR_RRC, "[UL] " UE_LOG_FMT " " fmt, UE_LOG_ARGS(ue_context) __VA_OPT__(,) __VA_ARGS__)
#include "nr_rrc_proto.h" //should be put here otherwise compilation error
#endif
openair2/RRC/NR/rrc_gNB.c
+18 -11
View File
@@ -211,7 +211,7 @@ static void init_NR_SI(gNB_RRC_INST *rrc)
rrc->carrier.SIB23 = (uint8_t *) malloc16(100);
AssertFatal(rrc->carrier.SIB23 != NULL, "cannot allocate memory for SIB");
rrc->carrier.sizeof_SIB23 = do_SIB23_NR(&rrc->carrier);
LOG_I(NR_RRC,"do_SIB23_NR, size %d \n ", rrc->carrier.sizeof_SIB23);
LOG_I(NR_RRC, "do_SIB23_NR, size %d\n", rrc->carrier.sizeof_SIB23);
AssertFatal(rrc->carrier.sizeof_SIB23 != 255,"FATAL, RC.nrrrc[mod].carrier[CC_id].sizeof_SIB23 == 255");
}
@@ -291,7 +291,7 @@ static void rrc_gNB_process_AdditionRequestInformation(const module_id_t gnb_mod
AssertFatal(cg_configinfo->criticalExtensions.choice.c1->present == NR_CG_ConfigInfo__criticalExtensions__c1_PR_cg_ConfigInfo,
"ueCapabilityInformation not present\n");
parse_CG_ConfigInfo(rrc,cg_configinfo,m);
LOG_A(NR_RRC, "Successfully parsed CG_ConfigInfo of size %zu bits. (%zu bytes)\n",
LOG_I(NR_RRC, "Successfully parsed CG_ConfigInfo of size %zu bits. (%zu bytes)\n",
dec_rval.consumed, (dec_rval.consumed +7/8));
}
@@ -400,7 +400,7 @@ static void rrc_gNB_generate_RRCSetup(instance_t instance,
int masterCellGroup_len)
//-----------------------------------------------------------------------------
{
LOG_I(NR_RRC, "rrc_gNB_generate_RRCSetup for RNTI %04x\n", rnti);
LOG_UE_DL_EVENT(&ue_context_pP->ue_context, "Send RRC Setup\n");
gNB_RRC_UE_t *ue_p = &ue_context_pP->ue_context;
gNB_RRC_INST *rrc = RC.nrrrc[instance];
@@ -430,9 +430,9 @@ static void rrc_gNB_generate_RRCSetup(instance_t instance,
static void rrc_gNB_generate_RRCReject(module_id_t module_id, rrc_gNB_ue_context_t *const ue_context_pP)
//-----------------------------------------------------------------------------
{
LOG_I(NR_RRC, "rrc_gNB_generate_RRCReject \n");
gNB_RRC_INST *rrc = RC.nrrrc[module_id];
gNB_RRC_UE_t *ue_p = &ue_context_pP->ue_context;
LOG_A(NR_RRC, "Send RRCReject to RNTI %04x\n", ue_p->rnti);
unsigned char buf[1024];
int size = do_RRCReject(buf);
@@ -466,7 +466,6 @@ static void rrc_gNB_generate_RRCReject(module_id_t module_id, rrc_gNB_ue_context
static void rrc_gNB_process_RRCSetupComplete(gNB_RRC_INST *rrc, gNB_RRC_UE_t *UE, NR_RRCSetupComplete_IEs_t *rrcSetupComplete)
//-----------------------------------------------------------------------------
{
LOG_A(NR_RRC, "UE %d Processing NR_RRCSetupComplete from UE\n", UE->rrc_ue_id);
UE->Srb[1].Active = 1;
UE->Srb[2].Active = 0;
@@ -568,7 +567,7 @@ static void rrc_gNB_generate_dedicatedRRCReconfiguration(gNB_RRC_INST *rrc, gNB_
int size = rrc_gNB_encode_RRCReconfiguration(rrc, ue_p, xid, dedicatedNAS_MessageList, buffer, sizeof(buffer), false);
DevAssert(size > 0 && size <= sizeof(buffer));
LOG_I(NR_RRC, "UE %d: Generate RRCReconfiguration (bytes %d, xid %d)\n", ue_p->rrc_ue_id, size, xid);
LOG_UE_DL_EVENT(ue_p, "Generate RRCReconfiguration (bytes %d, xid %d)\n", size, xid);
nr_rrc_transfer_protected_rrc_message(rrc, ue_p, DCCH, buffer, size);
}
@@ -825,7 +824,7 @@ static void rrc_gNB_generate_RRCReestablishment(rrc_gNB_ue_context_t *ue_context
uint32_t ssb_arfcn = get_ssb_arfcn(du);
int size = do_RRCReestablishment(ue_context_pP, buffer, NR_RRC_BUF_SIZE, xid, cell_info->nr_pci, ssb_arfcn);
LOG_I(NR_RRC, "[RAPROC] UE %04x Logical Channel DL-DCCH, Generating NR_RRCReestablishment (bytes %d)\n", ue_p->rnti, size);
LOG_A(NR_RRC, "Send RRCReestablishment [%d bytes] to RNTI %04x\n", size, ue_p->rnti);
/* Ciphering and Integrity according to TS 33.501 */
nr_pdcp_entity_security_keys_and_algos_t security_parameters;
@@ -1053,6 +1052,7 @@ static void rrc_handle_RRCSetupRequest(gNB_RRC_INST *rrc,
gNB_RRC_UE_t *UE = &ue_context_p->ue_context;
UE = &ue_context_p->ue_context;
UE->establishment_cause = rrcSetupRequest->establishmentCause;
UE->nr_cellid = msg->nr_cellid;
UE->masterCellGroup = cellGroupConfig;
activate_srb(UE, 1);
rrc_gNB_generate_RRCSetup(0, msg->crnti, ue_context_p, msg->du2cu_rrc_container, msg->du2cu_rrc_container_length);
@@ -1202,6 +1202,7 @@ static void rrc_handle_RRCReestablishmentRequest(gNB_RRC_INST *rrc,
// update with new RNTI, and update secondary UE association
UE->rnti = msg->crnti;
UE->nr_cellid = msg->nr_cellid;
f1_ue_data_t ue_data = cu_get_f1_ue_data(UE->rrc_ue_id);
ue_data.secondary_ue = msg->gNB_DU_ue_id;
cu_remove_f1_ue_data(UE->rrc_ue_id);
@@ -1399,6 +1400,8 @@ void rrc_forward_ue_nas_message(gNB_RRC_INST *rrc, gNB_RRC_UE_t *UE)
if (UE->nas_pdu.buffer == NULL || UE->nas_pdu.length == 0)
return; // no problem: the UE will re-request a NAS PDU
LOG_UE_DL_EVENT(UE, "Send DL Information Transfer [%d bytes]\n", UE->nas_pdu.length);
uint8_t buffer[4096];
unsigned int xid = rrc_gNB_get_next_transaction_identifier(rrc->module_id);
uint32_t length = do_NR_DLInformationTransfer(buffer, sizeof(buffer), xid, UE->nas_pdu.length, UE->nas_pdu.buffer);
@@ -1420,7 +1423,6 @@ static void handle_ueCapabilityInformation(gNB_RRC_INST *rrc, gNB_RRC_UE_t *UE,
return;
}
LOG_I(NR_RRC, "UE %d: received UE capabilities (xid %d)\n", UE->rrc_ue_id, xid);
int eutra_index = -1;
if (ue_cap_info->criticalExtensions.present == NR_UECapabilityInformation__criticalExtensions_PR_ueCapabilityInformation) {
@@ -1437,6 +1439,7 @@ static void handle_ueCapabilityInformation(gNB_RRC_INST *rrc, gNB_RRC_UE_t *UE,
LOG_E(RRC, "could not encode UE-CapabilityRAT-ContainerList, abort handling capabilities\n");
return;
}
LOG_UE_UL_EVENT(UE, "Received UE capabilities\n");
for (int i = 0; i < ue_CapabilityRAT_ContainerList->list.count; i++) {
const NR_UE_CapabilityRAT_Container_t *ue_cap_container = ue_CapabilityRAT_ContainerList->list.array[i];
@@ -1591,7 +1594,6 @@ static void handle_rrcReconfigurationComplete(gNB_RRC_INST *rrc, gNB_RRC_UE_t *U
{
uint8_t xid = reconfig_complete->rrc_TransactionIdentifier;
UE->ue_reconfiguration_counter++;
LOG_I(NR_RRC, "UE %d: Receive RRC Reconfiguration Complete message (xid %d)\n", UE->rrc_ue_id, xid);
switch (UE->xids[xid]) {
case RRC_PDUSESSION_RELEASE: {
@@ -1692,10 +1694,12 @@ static int rrc_gNB_decode_dcch(gNB_RRC_INST *rrc, const f1ap_ul_rrc_message_t *m
break;
case NR_UL_DCCH_MessageType__c1_PR_rrcReconfigurationComplete:
LOG_UE_UL_EVENT(UE, "Received RRCReconfigurationComplete\n");
handle_rrcReconfigurationComplete(rrc, UE, ul_dcch_msg->message.choice.c1->choice.rrcReconfigurationComplete);
break;
case NR_UL_DCCH_MessageType__c1_PR_rrcSetupComplete:
LOG_UE_UL_EVENT(UE, "Received RRCSetupComplete (RRC_CONNECTED reached)\n");
handle_rrcSetupComplete(rrc, UE, ul_dcch_msg->message.choice.c1->choice.rrcSetupComplete);
break;
@@ -1704,10 +1708,12 @@ static int rrc_gNB_decode_dcch(gNB_RRC_INST *rrc, const f1ap_ul_rrc_message_t *m
break;
case NR_UL_DCCH_MessageType__c1_PR_ulInformationTransfer:
LOG_UE_UL_EVENT(UE, "Received RRC UL Information Transfer [%d bytes]\n", msg->rrc_container_length);
rrc_gNB_send_NGAP_UPLINK_NAS(rrc, UE, ul_dcch_msg);
break;
case NR_UL_DCCH_MessageType__c1_PR_securityModeComplete:
LOG_UE_UL_EVENT(UE, "Received Security Mode Complete\n");
/* configure ciphering */
nr_rrc_pdcp_config_security(UE, true);
UE->as_security_active = true;
@@ -1740,6 +1746,7 @@ static int rrc_gNB_decode_dcch(gNB_RRC_INST *rrc, const f1ap_ul_rrc_message_t *m
break;
case NR_UL_DCCH_MessageType__c1_PR_rrcReestablishmentComplete:
LOG_UE_UL_EVENT(UE, "Received RRCReestablishmentComplete\n");
handle_rrcReestablishmentComplete(rrc, UE, ul_dcch_msg->message.choice.c1->choice.rrcReestablishmentComplete);
break;
@@ -2107,6 +2114,7 @@ static void rrc_CU_process_ue_context_modification_response(MessageDef *msg_p, i
nr_ho_source_cu_t *source_ctx = UE->ho_context->source;
DevAssert(source_ctx->old_rnti == UE->rnti);
UE->rnti = target_ctx->new_rnti;
UE->nr_cellid = target_ctx->du->setup_req->cell[0].info.nr_cellid;
}
}
@@ -2668,8 +2676,7 @@ void rrc_gNB_generate_RRCRelease(gNB_RRC_INST *rrc, gNB_RRC_UE_t *UE)
uint8_t buffer[NR_RRC_BUF_SIZE] = {0};
int size = do_NR_RRCRelease(buffer, NR_RRC_BUF_SIZE, rrc_gNB_get_next_transaction_identifier(rrc->module_id));
LOG_I(NR_RRC, "UE %d: Generate RRCRelease (bytes %d)\n", UE->rrc_ue_id, size);
LOG_UE_DL_EVENT(UE, "Send RRC Release\n");
f1_ue_data_t ue_data = cu_get_f1_ue_data(UE->rrc_ue_id);
RETURN_IF_INVALID_ASSOC_ID(ue_data.du_assoc_id);
f1ap_ue_context_release_cmd_t ue_context_release_cmd = {
openair2/RRC/NR/rrc_gNB_NGAP.c
+4 -6
View File
@@ -615,11 +615,10 @@ static void set_UE_security_algos(const gNB_RRC_INST *rrc, gNB_RRC_UE_t *UE, con
UE->ciphering_algorithm = cipheringAlgorithm;
UE->integrity_algorithm = integrityProtAlgorithm;
LOG_I(NR_RRC,
"[UE %d] Selected security algorithms: ciphering %lx, integrity %x\n",
UE->rrc_ue_id,
cipheringAlgorithm,
integrityProtAlgorithm);
LOG_UE_EVENT(UE,
"Selected security algorithms: ciphering %lx, integrity %x\n",
cipheringAlgorithm,
integrityProtAlgorithm);
}
//------------------------------------------------------------------------------
@@ -1143,7 +1142,6 @@ void rrc_gNB_send_NGAP_UE_CONTEXT_RELEASE_COMPLETE(instance_t instance,
NGAP_UE_CONTEXT_RELEASE_COMPLETE(msg).num_pdu_sessions = num_pdu;
for (int i = 0; i < num_pdu; ++i)
NGAP_UE_CONTEXT_RELEASE_COMPLETE(msg).pdu_session_id[i] = pdu_session_id[i];
LOG_W(RRC, "trigger release with %d pdu\n", num_pdu);
itti_send_msg_to_task(TASK_NGAP, instance, msg);
}
openair2/RRC/NR/rrc_gNB_UE_context.c
+7 -7
View File
@@ -142,11 +142,11 @@ void rrc_gNB_remove_ue_context(gNB_RRC_INST *rrc_instance_pP, rrc_gNB_ue_context
return;
}
LOG_UE_EVENT(&ue_context_pP->ue_context, "Remove UE context\n");
RB_REMOVE(rrc_nr_ue_tree_s, &rrc_instance_pP->rrc_ue_head, ue_context_pP);
uid_linear_allocator_free(&rrc_instance_pP->uid_allocator, ue_context_pP->ue_context.rrc_ue_id - 1);
cu_remove_f1_ue_data(ue_context_pP->ue_context.rrc_ue_id);
rrc_gNB_free_mem_ue_context(ue_context_pP);
LOG_I(NR_RRC, "Removed UE context\n");
}
//-----------------------------------------------------------------------------
@@ -204,11 +204,11 @@ rrc_gNB_ue_context_t *rrc_gNB_create_ue_context(sctp_assoc_t assoc_id,
cu_add_f1_ue_data(ue->rrc_ue_id, &ue_data);
RB_INSERT(rrc_nr_ue_tree_s, &rrc_instance_pP->rrc_ue_head, ue_context_p);
LOG_I(NR_RRC,
"Created new UE context: CU UE ID %u DU UE ID %u (rnti: %04x, random ue id %lx)\n",
ue->rrc_ue_id,
du_ue_id,
ue->rnti,
ue->random_ue_identity);
LOG_UE_EVENT(ue,
"Create UE context: CU UE ID %u DU UE ID %u (rnti: %04x, random ue id %lx)\n",
ue->rrc_ue_id,
du_ue_id,
ue->rnti,
ue->random_ue_identity);
return ue_context_p;
}
openair2/RRC/NR/rrc_gNB_cuup.c
+2 -2
View File
@@ -46,10 +46,10 @@ static const nr_rrc_cuup_container_t *select_cuup_slice(const struct rrc_cuup_tr
for (int s = 0; s < sr->plmn[p].supported_slices; ++s) {
e1ap_nssai_t *nssai = &sr->plmn[p].slice[s];
if (nssai->sst == sst && nssai->sd == sd) {
LOG_A(RRC, "selecting CU-UP ID %ld based on exact NSSAI match (%d:0x%06x)\n", sr->gNB_cu_up_id, sst, sd);
LOG_UE_EVENT(ue, "selecting CU-UP ID %ld based on exact NSSAI match (%d:0x%06x)\n", sr->gNB_cu_up_id, sst, sd);
return cuup; /* exact match */
} else if (nssai->sst == sst && second_best_match == NULL) {
LOG_I(RRC, "second best match: CU-UP ID %ld matches SST %d\n", sr->gNB_cu_up_id, sst);
LOG_UE_EVENT(ue, "second best match: CU-UP ID %ld matches SST %d\n", sr->gNB_cu_up_id, sst);
second_best_match = cuup; /* only the SST matches -> "good enough" */
}
}