diff --git a/openair2/RRC/NR/nr_rrc_defs.h b/openair2/RRC/NR/nr_rrc_defs.h index 7966ed8e9a..463ba84ce1 100644 --- a/openair2/RRC/NR/nr_rrc_defs.h +++ b/openair2/RRC/NR/nr_rrc_defs.h @@ -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 @@ -427,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_P) (ue_P)->nr_cellid, (ue_P)->rrc_ue_id, (ue_P)->rnti + +#define LOG_UE_DL_EVENT(ue_P, fMt, ...) LOG_A(NR_RRC, "[DL] " UE_LOG_FMT " " fMt, UE_LOG_ARGS(ue_P) __VA_OPT__(,) __VA_ARGS__) +#define LOG_UE_EVENT(ue_P, fMt, ...) LOG_A(NR_RRC, "[--] " UE_LOG_FMT " " fMt, UE_LOG_ARGS(ue_P) __VA_OPT__(,) __VA_ARGS__) +#define LOG_UE_UL_EVENT(ue_P, fMt, ...) LOG_A(NR_RRC, "[UL] " UE_LOG_FMT " " fMt, UE_LOG_ARGS(ue_P) __VA_OPT__(,) __VA_ARGS__) + #include "nr_rrc_proto.h" //should be put here otherwise compilation error #endif diff --git a/openair2/RRC/NR/rrc_gNB.c b/openair2/RRC/NR/rrc_gNB.c index b1352050fa..208b772d6a 100644 --- a/openair2/RRC/NR/rrc_gNB.c +++ b/openair2/RRC/NR/rrc_gNB.c @@ -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; @@ -1401,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); @@ -1422,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) { @@ -1439,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]; @@ -1593,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: { @@ -1694,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; @@ -1706,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; @@ -1742,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; @@ -2671,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 = { diff --git a/openair2/RRC/NR/rrc_gNB_NGAP.c b/openair2/RRC/NR/rrc_gNB_NGAP.c index 8c45728523..6a35f61b3f 100644 --- a/openair2/RRC/NR/rrc_gNB_NGAP.c +++ b/openair2/RRC/NR/rrc_gNB_NGAP.c @@ -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); } diff --git a/openair2/RRC/NR/rrc_gNB_UE_context.c b/openair2/RRC/NR/rrc_gNB_UE_context.c index 82c5d29116..15f644955d 100644 --- a/openair2/RRC/NR/rrc_gNB_UE_context.c +++ b/openair2/RRC/NR/rrc_gNB_UE_context.c @@ -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; } diff --git a/openair2/RRC/NR/rrc_gNB_cuup.c b/openair2/RRC/NR/rrc_gNB_cuup.c index d37a1f430b..729f5f28b4 100644 --- a/openair2/RRC/NR/rrc_gNB_cuup.c +++ b/openair2/RRC/NR/rrc_gNB_cuup.c @@ -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" */ } }