f1ap-cu: make the prefix logging consistent with DU

Author: frankist

include/srsran/support/prefixed_logger.h

@@ -25,8 +25,8 @@ template <typename Prefix>
 class prefixed_logger
 {
 public:
-  prefixed_logger(const std::string& log_name, Prefix prefix_) :
-    logger(srslog::fetch_basic_logger(log_name, false)), prefix(prefix_)
+  prefixed_logger(const std::string& log_name, Prefix prefix_, const char* prefix_separator_ = "") :
+    logger(srslog::fetch_basic_logger(log_name, false)), prefix(prefix_), prefix_separator(prefix_separator_)
   {
   }
 
@@ -196,6 +196,7 @@ class prefixed_logger
 private:
   srslog::basic_logger& logger;
   Prefix                prefix;
+  const char*           prefix_separator;
 
   template <typename... Args>
   void log_helper(srslog::log_channel& channel, const char* fmt, Args&&... args) const
@@ -205,7 +206,7 @@ class prefixed_logger
     }
     fmt::memory_buffer buffer;
     fmt::format_to(buffer, fmt, std::forward<Args>(args)...);
-    channel("{}{}", prefix, to_c_str(buffer));
+    channel("{}{}{}", prefix, prefix_separator, to_c_str(buffer));
   }
 
   template <typename It, typename... Args>
@@ -216,7 +217,7 @@ class prefixed_logger
     }
     fmt::memory_buffer buffer;
     fmt::format_to(buffer, fmt, std::forward<Args>(args)...);
-    channel(it_begin, it_end, "{}{}", prefix, to_c_str(buffer));
+    channel(it_begin, it_end, "{}{}{}", prefix, prefix_separator, to_c_str(buffer));
   }
 
   template <typename... Args>
@@ -227,7 +228,7 @@ class prefixed_logger
     }
     fmt::memory_buffer buffer;
     fmt::format_to(buffer, fmt, std::forward<Args>(args)...);
-    channel(msg, len, "{}{}", prefix, to_c_str(buffer));
+    channel(msg, len, "{}{}{}", prefix, prefix_separator, to_c_str(buffer));
   }
 };
 

lib/f1ap/common/proc_logger.h

@@ -0,0 +1,67 @@
+/*
+ *
+ * Copyright 2021-2024 Software Radio Systems Limited
+ *
+ * By using this file, you agree to the terms and conditions set
+ * forth in the LICENSE file which can be found at the top level of
+ * the distribution.
+ *
+ */
+
+#pragma once
+
+#include "srsran/f1ap/common/f1ap_ue_id.h"
+
+namespace srsran {
+
+struct f1ap_common_log_prefix {
+  f1ap_common_log_prefix(gnb_du_ue_f1ap_id_t du_ue_id_, const char* proc_name_ = nullptr) :
+    du_ue_id(du_ue_id_), proc_name(proc_name_)
+  {
+  }
+  f1ap_common_log_prefix(gnb_du_ue_f1ap_id_t du_ue_id_,
+                         gnb_cu_ue_f1ap_id_t cu_ue_id_,
+                         const char*         proc_name_ = nullptr) :
+    du_ue_id(du_ue_id_), cu_ue_id(cu_ue_id_), proc_name(proc_name_)
+  {
+  }
+  f1ap_common_log_prefix(gnb_cu_ue_f1ap_id_t cu_ue_id_, const char* proc_name_ = nullptr) :
+    cu_ue_id(cu_ue_id_), proc_name(proc_name_)
+  {
+  }
+
+  gnb_du_ue_f1ap_id_t du_ue_id  = gnb_du_ue_f1ap_id_t::invalid;
+  gnb_cu_ue_f1ap_id_t cu_ue_id  = gnb_cu_ue_f1ap_id_t::invalid;
+  const char*         proc_name = nullptr;
+};
+
+} // namespace srsran
+namespace fmt {
+
+template <>
+struct formatter<srsran::f1ap_common_log_prefix> {
+  template <typename ParseContext>
+  auto parse(ParseContext& ctx)
+  {
+    return ctx.begin();
+  }
+
+  template <typename FormatContext>
+  auto format(const srsran::f1ap_common_log_prefix& prefix, FormatContext& ctx)
+  {
+    bool first_id = true;
+    auto get_sep  = [&first_id]() { return std::exchange(first_id, false) ? "" : " "; };
+    if (prefix.du_ue_id != srsran::gnb_du_ue_f1ap_id_t::invalid) {
+      format_to(ctx.out(), "{}GNB-DU-UE-F1AP-ID={}", get_sep(), prefix.du_ue_id);
+    }
+    if (prefix.cu_ue_id != srsran::gnb_cu_ue_f1ap_id_t::invalid) {
+      format_to(ctx.out(), "{}GNB-CU-UE-F1AP-ID={}", get_sep(), prefix.cu_ue_id);
+    }
+    if (prefix.proc_name != nullptr) {
+      format_to(ctx.out(), "{}proc=\"{}\"", get_sep(), prefix.proc_name);
+    }
+    return ctx.out();
+  }
+};
+
+} // namespace fmt

lib/f1ap/cu_cp/procedures/ue_context_modification_procedure.cpp

@@ -22,15 +22,15 @@ ue_context_modification_procedure::ue_context_modification_procedure(
     const f1ap_ue_context_modification_request& request_,
     f1ap_ue_context&                            ue_ctxt_,
     f1ap_message_notifier&                      f1ap_notif_) :
-  request(request_), ue_ctxt(ue_ctxt_), f1ap_notifier(f1ap_notif_)
+  request(request_), ue_ctxt(ue_ctxt_), f1ap_notifier(f1ap_notif_), logger(srslog::fetch_basic_logger("CU-CP-F1"))
 {
 }
 
 void ue_context_modification_procedure::operator()(coro_context<async_task<f1ap_ue_context_modification_response>>& ctx)
 {
   CORO_BEGIN(ctx);
 
-  ue_ctxt.logger.log_debug("\"{}\" initialized", name());
+  logger.debug("{}: Procedure started...", f1ap_ue_log_prefix{ue_ctxt.ue_ids, name()});
 
   // Subscribe to respective publisher to receive UE CONTEXT MODIFICATION RESPONSE/FAILURE message.
   transaction_sink.subscribe_to(ue_ctxt.ev_mng.context_modification_outcome);
@@ -60,7 +60,9 @@ void ue_context_modification_procedure::send_ue_context_modification_request()
   if (ue_ctxt.logger.get_basic_logger().debug.enabled()) {
     asn1::json_writer js;
     f1ap_ue_ctxt_mod_request_msg.pdu.to_json(js);
-    ue_ctxt.logger.log_debug("Containerized UeContextModificationRequest: {}", js.to_string());
+    logger.debug("{}: Containerized UEContextModificationRequest: {}",
+                 f1ap_ue_log_prefix{ue_ctxt.ue_ids, name()},
+                 js.to_string());
   }
 
   // send UE context modification request message
@@ -71,34 +73,27 @@ f1ap_ue_context_modification_response ue_context_modification_procedure::create_
 {
   f1ap_ue_context_modification_response res{};
 
+  auto logger_prefix = f1ap_ue_log_prefix{ue_ctxt.ue_ids, name()};
+
   if (transaction_sink.successful()) {
     const asn1::f1ap::ue_context_mod_resp_s& resp = transaction_sink.response();
-    ue_ctxt.logger.log_debug("Received UeContextModificationResponse");
-    if (ue_ctxt.logger.get_basic_logger().debug.enabled()) {
-      asn1::json_writer js;
-      resp.to_json(js);
-      ue_ctxt.logger.log_debug("Containerized UeContextModificationResponse: {}", js.to_string());
-    }
+
+    logger.info("{}: Procedure finished successfully", logger_prefix);
+
     fill_f1ap_ue_context_modification_response(res, resp);
 
-    ue_ctxt.logger.log_debug("\"{}\" finalized", name());
   } else if (transaction_sink.failed()) {
     const asn1::f1ap::ue_context_mod_fail_s& fail = transaction_sink.failure();
-    ue_ctxt.logger.log_debug("Received UeContextModificationFailure cause={}", get_cause_str(fail->cause));
-    if (ue_ctxt.logger.get_basic_logger().debug.enabled()) {
-      asn1::json_writer js;
-      (*transaction_sink.failure()).to_json(js);
-      ue_ctxt.logger.log_debug("Containerized UeContextModificationFailure: {}", js.to_string());
-    }
-    fill_f1ap_ue_context_modification_response(res, fail);
 
-    ue_ctxt.logger.log_error("\"{}\" failed", name());
+    logger.warning("{}: Procedure failed. Cause: {}", logger_prefix, get_cause_str(fail->cause));
+
+    fill_f1ap_ue_context_modification_response(res, fail);
   } else {
-    ue_ctxt.logger.log_warning("UeContextModificationResponse timeout");
+    logger.warning("{}: Procedure failed. Cause: Timeout reached for UEContextModificationResponse reception",
+                   logger_prefix);
+
     res.success = false;
     res.cause   = cause_misc_t::unspecified;
-
-    ue_ctxt.logger.log_error("\"{}\" failed", name());
   }
 
   return res;

lib/f1ap/cu_cp/procedures/ue_context_modification_procedure.h

@@ -42,6 +42,7 @@ class ue_context_modification_procedure
   const f1ap_ue_context_modification_request request;
   f1ap_ue_context&                           ue_ctxt;
   f1ap_message_notifier&                     f1ap_notifier;
+  srslog::basic_logger&                      logger;
 
   protocol_transaction_outcome_observer<asn1::f1ap::ue_context_mod_resp_s, asn1::f1ap::ue_context_mod_fail_s>
       transaction_sink;

lib/f1ap/cu_cp/procedures/ue_context_release_procedure.cpp

@@ -21,7 +21,7 @@ using namespace asn1::f1ap;
 ue_context_release_procedure::ue_context_release_procedure(const f1ap_ue_context_release_command& cmd_,
                                                            f1ap_ue_context&                       ue_ctxt_,
                                                            f1ap_message_notifier&                 f1ap_notif_) :
-  ue_ctxt(ue_ctxt_), f1ap_notifier(f1ap_notif_)
+  ue_ctxt(ue_ctxt_), f1ap_notifier(f1ap_notif_), logger(srslog::fetch_basic_logger("CU-CP-F1"))
 {
   command->gnb_cu_ue_f1ap_id = gnb_cu_ue_f1ap_id_to_uint(ue_ctxt.ue_ids.cu_ue_f1ap_id);
   command->gnb_du_ue_f1ap_id = gnb_du_ue_f1ap_id_to_uint(ue_ctxt.ue_ids.du_ue_f1ap_id);
@@ -41,7 +41,7 @@ void ue_context_release_procedure::operator()(coro_context<async_task<ue_index_t
 {
   CORO_BEGIN(ctx);
 
-  ue_ctxt.logger.log_debug("\"{}\" initialized", name());
+  logger.debug("{}: Procedure started...", f1ap_ue_log_prefix{ue_ctxt.ue_ids, name()});
 
   transaction_sink.subscribe_to(ue_ctxt.ev_mng.context_release_complete);
 
@@ -69,7 +69,8 @@ void ue_context_release_procedure::send_ue_context_release_command()
   if (ue_ctxt.logger.get_basic_logger().debug.enabled()) {
     asn1::json_writer js;
     f1ap_ue_ctxt_rel_msg.pdu.to_json(js);
-    ue_ctxt.logger.log_debug("Containerized UeContextReleaseCommand: {}", js.to_string());
+    logger.debug(
+        "{}: Containerized UEContextReleaseCommand: {}", f1ap_ue_log_prefix{ue_ctxt.ue_ids, name()}, js.to_string());
   }
 
   // send UE Context Release Command
@@ -79,15 +80,13 @@ void ue_context_release_procedure::send_ue_context_release_command()
 ue_index_t
 ue_context_release_procedure::create_ue_context_release_complete(const asn1::f1ap::ue_context_release_complete_s& msg)
 {
-  ue_ctxt.logger.log_debug("Received UeContextReleaseComplete");
-
   ue_index_t ret = ue_index_t::invalid;
 
   if (msg->gnb_du_ue_f1ap_id == gnb_du_ue_f1ap_id_to_uint(ue_ctxt.ue_ids.du_ue_f1ap_id)) {
     ret = ue_ctxt.ue_ids.ue_index;
-    ue_ctxt.logger.log_debug("\"{}\" finalized", name());
+    logger.info("{}: Procedure finished successfully.", f1ap_ue_log_prefix{ue_ctxt.ue_ids, name()});
   } else {
-    ue_ctxt.logger.log_error("\"{}\" failed", name());
+    logger.warning("{}: Procedure failed.", f1ap_ue_log_prefix{ue_ctxt.ue_ids, name()});
   }
 
   return ret;

lib/f1ap/cu_cp/procedures/ue_context_release_procedure.h

@@ -42,6 +42,7 @@ class ue_context_release_procedure
   f1ap_ue_context&                     ue_ctxt;
   asn1::f1ap::ue_context_release_cmd_s command;
   f1ap_message_notifier&               f1ap_notifier;
+  srslog::basic_logger&                logger;
 
   protocol_transaction_outcome_observer<asn1::f1ap::ue_context_release_complete_s> transaction_sink;
 };

lib/f1ap/cu_cp/procedures/ue_context_setup_procedure.cpp

@@ -10,6 +10,7 @@
 
 #include "ue_context_setup_procedure.h"
 #include "../f1ap_asn1_helpers.h"
+#include "cu_cp/ue_context/f1ap_ue_logger.h"
 #include "srsran/f1ap/common/f1ap_message.h"
 
 using namespace srsran;
@@ -88,7 +89,7 @@ bool ue_context_setup_procedure::allocate_cu_ue_id()
 
   // Create UE context and store it.
   f1ap_ue_context& ue_ctxt = ue_ctxt_list.add_ue(request.ue_index, tmp_cu_ue_f1ap_id);
-  logger.debug("ue={}: Added UE (cu_ue_f1ap_id={}, du_ue_f1ap_id=<n/a>)", ue_ctxt.ue_ids.ue_index, tmp_cu_ue_f1ap_id);
+  logger.debug("{}: UE successfully created.", f1ap_ue_log_prefix{ue_ctxt.ue_ids, name()});
 
   // Store identifiers.
   new_cu_ue_f1ap_id = tmp_cu_ue_f1ap_id;

lib/f1ap/cu_cp/ue_context/f1ap_cu_ue_context.h

@@ -19,12 +19,6 @@
 namespace srsran {
 namespace srs_cu_cp {
 
-struct f1ap_ue_ids {
-  const ue_index_t          ue_index      = ue_index_t::invalid;
-  const gnb_cu_ue_f1ap_id_t cu_ue_f1ap_id = gnb_cu_ue_f1ap_id_t::invalid;
-  gnb_du_ue_f1ap_id_t       du_ue_f1ap_id = gnb_du_ue_f1ap_id_t::invalid;
-};
-
 struct f1ap_ue_context {
   f1ap_ue_ids                ue_ids;
   f1ap_rrc_message_notifier* rrc_notifier       = nullptr;
@@ -35,7 +29,7 @@ struct f1ap_ue_context {
   f1ap_ue_logger                logger;
 
   f1ap_ue_context(ue_index_t ue_index_, gnb_cu_ue_f1ap_id_t cu_ue_f1ap_id_, timer_factory timers_) :
-    ue_ids({ue_index_, cu_ue_f1ap_id_}), ev_mng(timers_), logger("CU-CP-F1", {ue_index_, cu_ue_f1ap_id_})
+    ue_ids({ue_index_, cu_ue_f1ap_id_}), ev_mng(timers_), logger("CU-CP-F1", {ue_ids}, " ")
   {
   }
 };

lib/f1ap/cu_cp/ue_context/f1ap_ue_ids.h

@@ -0,0 +1,27 @@
+/*
+ *
+ * Copyright 2021-2024 Software Radio Systems Limited
+ *
+ * By using this file, you agree to the terms and conditions set
+ * forth in the LICENSE file which can be found at the top level of
+ * the distribution.
+ *
+ */
+
+#pragma once
+
+#include "srsran/cu_cp/cu_cp_types.h"
+#include "srsran/f1ap/common/f1ap_ue_id.h"
+
+namespace srsran {
+namespace srs_cu_cp {
+
+/// Identifiers for a UE in F1AP-CU.
+struct f1ap_ue_ids {
+  const ue_index_t          ue_index      = ue_index_t::invalid;
+  const gnb_cu_ue_f1ap_id_t cu_ue_f1ap_id = gnb_cu_ue_f1ap_id_t::invalid;
+  gnb_du_ue_f1ap_id_t       du_ue_f1ap_id = gnb_du_ue_f1ap_id_t::invalid;
+};
+
+} // namespace srs_cu_cp
+} // namespace srsran