RRC: more UE tracability through LOG_A

It is difficult to keep track of a "UE lifecycle". To make this more
easy, add LOG_A at major UE RRC messages.

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

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 = {

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,
+  LOG_UE_EVENT(UE,
-        "[UE %d] Selected security algorithms: ciphering %lx, integrity %x\n",
+               "Selected security algorithms: ciphering %lx, integrity %x\n",
-        UE->rrc_ue_id,
+               cipheringAlgorithm,
-        cipheringAlgorithm,
+               integrityProtAlgorithm);
-        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

@@ -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,
+  LOG_UE_EVENT(ue,
-        "Created new UE context: CU UE ID %u DU UE ID %u (rnti: %04x, random ue id %lx)\n",
+               "Create UE context: CU UE ID %u DU UE ID %u (rnti: %04x, random ue id %lx)\n",
-        ue->rrc_ue_id,
+               ue->rrc_ue_id,
-        du_ue_id,
+               du_ue_id,
-        ue->rnti,
+               ue->rnti,
-        ue->random_ue_identity);
+               ue->random_ue_identity);
   return ue_context_p;
 }

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" */
         }
       }