cu_up,pdu_session_manager: Add prefixed logger

Author: FabianEckermann

lib/cu_up/cu_up_impl.cpp

@@ -67,7 +67,7 @@ cu_up::cu_up(const cu_up_configuration& config_) : cfg(config_), main_ctrl_loop(
 
   // Bind/open the gateway, start handling of incoming traffic from UPF, e.g. echo
   if (not ngu_gw->create_and_bind()) {
-    logger.error("Failed to create and connect NG-U gateway.");
+    logger.error("Failed to create and connect NG-U gateway");
   }
   cfg.epoll_broker->register_fd(ngu_gw->get_socket_fd(), [this](int fd) { ngu_gw->receive(); });
 
@@ -110,7 +110,7 @@ void cu_up::start()
 
   std::unique_lock<std::mutex> lock(mutex);
   if (std::exchange(running, true)) {
-    logger.warning("CU-UP already started. Ignoring start request.");
+    logger.warning("CU-UP already started. Ignoring start request");
     return;
   }
 
@@ -136,7 +136,7 @@ void cu_up::start()
   // Block waiting for CU-UP setup to complete.
   fut.wait();
 
-  logger.info("CU-UP started successfully.");
+  logger.info("CU-UP started successfully");
 }
 
 void cu_up::stop()
@@ -166,7 +166,7 @@ void cu_up::stop()
   // Wait until the all tasks of the main loop are completed and main loop has stopped.
   while (not main_loop_stopped) {
     if (not cfg.cu_up_executor->execute(stop_cu_up_main_loop)) {
-      logger.error("Unable to stop CU-UP.");
+      logger.error("Unable to stop CU-UP");
       return;
     }
     std::this_thread::sleep_for(std::chrono::milliseconds(10));
@@ -306,7 +306,7 @@ cu_up::handle_bearer_context_setup_request(const e1ap_bearer_context_setup_reque
     logger.error("Could not create UE context");
     return response;
   }
-  logger.info("ue={} UE Created", ue_ctxt->get_index());
+  ue_ctxt->get_logger().log_info("UE created");
 
   // 2. Handle bearer context setup request
   for (const auto& pdu_session : msg.pdu_session_res_to_setup_list) {
@@ -334,14 +334,14 @@ cu_up::handle_bearer_context_setup_request(const e1ap_bearer_context_setup_reque
 e1ap_bearer_context_modification_response
 cu_up::handle_bearer_context_modification_request(const e1ap_bearer_context_modification_request& msg)
 {
-  logger.debug("Handling bearer context modification request ue={}", msg.ue_index);
-
   ue_context* ue_ctxt = ue_mng->find_ue(msg.ue_index);
   if (ue_ctxt == nullptr) {
     logger.error("Could not find UE context");
     return {};
   }
 
+  ue_ctxt->get_logger().log_debug("Handling bearer context modification request");
+
   e1ap_bearer_context_modification_response response = {};
   response.ue_index                                  = ue_ctxt->get_index();
   response.success                                   = true;
@@ -352,34 +352,34 @@ cu_up::handle_bearer_context_modification_request(const e1ap_bearer_context_modi
     // Traverse list of PDU sessions to be setup/modified
     for (const auto& pdu_session_item :
          msg.ng_ran_bearer_context_mod_request.value().pdu_session_res_to_setup_mod_list) {
-      logger.debug("Setup/Modification of psi={}", pdu_session_item.pdu_session_id);
+      ue_ctxt->get_logger().log_debug("Setup/Modification of psi={}", pdu_session_item.pdu_session_id);
       pdu_session_setup_result session_result = ue_ctxt->setup_pdu_session(pdu_session_item);
       process_successful_pdu_resource_setup_mod_outcome(response.pdu_session_resource_setup_list, session_result);
       response.success &= session_result.success; // Update final result.
     }
 
     // Traverse list of PDU sessions to be modified.
     for (const auto& pdu_session_item : msg.ng_ran_bearer_context_mod_request.value().pdu_session_res_to_modify_list) {
-      logger.debug("Modifying psi={}", pdu_session_item.pdu_session_id);
+      ue_ctxt->get_logger().log_debug("Modifying psi={}", pdu_session_item.pdu_session_id);
       pdu_session_modification_result session_result =
           ue_ctxt->modify_pdu_session(pdu_session_item, new_ul_tnl_info_required);
       process_successful_pdu_resource_modification_outcome(response.pdu_session_resource_modified_list,
                                                            response.pdu_session_resource_failed_to_modify_list,
                                                            session_result,
                                                            logger);
-      logger.debug("Modification {}", session_result.success ? "successful" : "failed");
+      ue_ctxt->get_logger().log_debug("Modification {}", session_result.success ? "successful" : "failed");
 
       response.success &= session_result.success; // Update final result.
     }
 
     // Traverse list of PDU sessions to be removed.
     for (const auto& pdu_session_item : msg.ng_ran_bearer_context_mod_request.value().pdu_session_res_to_rem_list) {
-      logger.info("Removing psi={}", pdu_session_item);
+      ue_ctxt->get_logger().log_info("Removing psi={}", pdu_session_item);
       ue_ctxt->remove_pdu_session(pdu_session_item);
       // There is no IE to confirm successful removal.
     }
   } else {
-    logger.warning("Ignoring empty Bearer Context Modification Request.");
+    ue_ctxt->get_logger().log_warning("Ignoring empty Bearer Context Modification Request");
   }
 
   // 3. Create response
@@ -393,9 +393,12 @@ void cu_up::handle_bearer_context_release_command(const e1ap_bearer_context_rele
 {
   ue_context* ue_ctxt = ue_mng->find_ue(msg.ue_index);
   if (ue_ctxt == nullptr) {
-    logger.error("ue={} not found. Discarding E1 Bearer Context Release Command.", msg.ue_index);
+    logger.error("ue={}: Discarding E1 Bearer Context Release Command. UE context not found", msg.ue_index);
     return;
   }
+
+  ue_ctxt->get_logger().log_debug("Received E1 Bearer Context Release Command");
+
   ue_mng->remove_ue(msg.ue_index);
 }
 

lib/cu_up/cu_up_ue_logger.h

@@ -0,0 +1,57 @@
+/*
+ *
+ * Copyright 2021-2023 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_up/cu_up_types.h"
+#include "srsran/support/prefixed_logger.h"
+#include "fmt/format.h"
+
+namespace srsran {
+namespace srs_cu_up {
+
+class cu_up_log_prefix
+{
+public:
+  cu_up_log_prefix(ue_index_t ue_index)
+  {
+    fmt::memory_buffer buffer;
+    fmt::format_to(buffer, "ue={}: ", ue_index);
+    prefix = srsran::to_c_str(buffer);
+  }
+  const char* to_c_str() const { return prefix.c_str(); }
+
+private:
+  std::string prefix;
+};
+
+using cu_up_ue_logger = prefixed_logger<cu_up_log_prefix>;
+
+} // namespace srs_cu_up
+} // namespace srsran
+
+namespace fmt {
+
+// associated formatter
+template <>
+struct formatter<srsran::srs_cu_up::cu_up_log_prefix> {
+  template <typename ParseContext>
+  auto parse(ParseContext& ctx) -> decltype(ctx.begin())
+  {
+    return ctx.begin();
+  }
+
+  template <typename FormatContext>
+  auto format(srsran::srs_cu_up::cu_up_log_prefix o, FormatContext& ctx)
+      -> decltype(std::declval<FormatContext>().out())
+  {
+    return format_to(ctx.out(), "{}", o.to_c_str());
+  }
+};
+} // namespace fmt

lib/cu_up/pdu_session_manager_impl.cpp

@@ -23,7 +23,7 @@ pdu_session_manager_impl::pdu_session_manager_impl(ue_index_t
                                                    const security::sec_as_config&       security_info_,
                                                    network_interface_config&            net_config_,
                                                    n3_interface_config&                 n3_config_,
-                                                   srslog::basic_logger&                logger_,
+                                                   cu_up_ue_logger&                     logger_,
                                                    unique_timer&                        ue_inactivity_timer_,
                                                    timer_factory                        timers_,
                                                    f1u_cu_up_gateway&                   f1u_gw_,
@@ -102,7 +102,7 @@ drb_setup_result pdu_session_manager_impl::handle_drb_to_setup_item(pdu_session&
   // Create  F1-U bearer
   expected<gtpu_teid_t> ret = f1u_teid_allocator.request_teid();
   if (not ret.has_value()) {
-    logger.error("ue={} could not allocate ul_teid", ue_index);
+    logger.log_error("Could not allocate ul_teid");
     return drb_result;
   }
   gtpu_teid_t f1u_ul_teid = ret.value();
@@ -136,8 +136,7 @@ drb_setup_result pdu_session_manager_impl::handle_drb_to_setup_item(pdu_session&
     auto& qos_flow                           = qos_flow_info;
     new_drb->qos_flows[qos_flow.qos_flow_id] = std::make_unique<qos_flow_context>(qos_flow);
     auto& new_qos_flow                       = new_drb->qos_flows[qos_flow.qos_flow_id];
-    logger.debug(
-        "Created QoS flow with qos_flow_id={} and five_qi={}", new_qos_flow->qos_flow_id, new_qos_flow->five_qi);
+    logger.log_debug("Created QoS flow with {} and {}", new_qos_flow->qos_flow_id, new_qos_flow->five_qi);
 
     sdap_config sdap_cfg = make_sdap_drb_config(drb_to_setup.sdap_cfg);
     new_session.sdap->add_mapping(
@@ -164,12 +163,13 @@ pdu_session_setup_result pdu_session_manager_impl::setup_pdu_session(const e1ap_
   pdu_session_result.cause                    = cause_radio_network_t::unspecified;
 
   if (pdu_sessions.find(session.pdu_session_id) != pdu_sessions.end()) {
-    logger.error("PDU Session {} already exists", session.pdu_session_id);
+    logger.log_error("PDU Session with psi={} already exists", session.pdu_session_id);
     return pdu_session_result;
   }
 
   if (pdu_sessions.size() >= MAX_NUM_PDU_SESSIONS_PER_UE) {
-    logger.error("PDU Session {} cannot be created, max number of PDU sessions reached", session.pdu_session_id);
+    logger.log_error("PDU Session for psi={} cannot be created. Max number of PDU sessions reached",
+                     session.pdu_session_id);
     return pdu_session_result;
   }
 
@@ -178,10 +178,10 @@ pdu_session_setup_result pdu_session_manager_impl::setup_pdu_session(const e1ap_
   const auto&                   ul_tunnel_info = new_session->ul_tunnel_info;
 
   // Get uplink transport address
-  logger.debug("PDU session {} uplink tunnel info: TEID={}, address={}",
-               session.pdu_session_id,
-               ul_tunnel_info.gtp_teid.value(),
-               ul_tunnel_info.tp_address);
+  logger.log_debug("PDU session uplink tunnel info: psi={} teid={} addr={}",
+                   session.pdu_session_id,
+                   ul_tunnel_info.gtp_teid.value(),
+                   ul_tunnel_info.tp_address);
 
   // Allocate local TEID
   new_session->local_teid = allocate_local_teid(new_session->pdu_session_id);
@@ -216,7 +216,7 @@ pdu_session_setup_result pdu_session_manager_impl::setup_pdu_session(const e1ap_
 
   // Register tunnel at demux
   if (!gtpu_rx_demux.add_tunnel(new_session->local_teid, new_session->gtpu->get_rx_upper_layer_interface())) {
-    logger.error(
+    logger.log_error(
         "PDU Session {} cannot be created. TEID {} already exists", session.pdu_session_id, new_session->local_teid);
     return pdu_session_result;
   }
@@ -261,7 +261,7 @@ pdu_session_manager_impl::modify_pdu_session(const e1ap_pdu_session_res_to_modif
   pdu_session_result.cause          = cause_radio_network_t::unspecified;
 
   if (pdu_sessions.find(session.pdu_session_id) == pdu_sessions.end()) {
-    logger.error("PDU Session {} doesn't exists", session.pdu_session_id);
+    logger.log_error("PDU Session {} doesn't exists", session.pdu_session_id);
     return pdu_session_result;
   }
 
@@ -284,7 +284,7 @@ pdu_session_manager_impl::modify_pdu_session(const e1ap_pdu_session_res_to_modif
     // find DRB in PDU session
     auto drb_iter = pdu_session->drbs.find(drb_to_mod.drb_id);
     if (drb_iter == pdu_session->drbs.end()) {
-      logger.warning("Cannot modify {} not found in psi={}", drb_to_mod.drb_id, session.pdu_session_id);
+      logger.log_warning("Cannot modify {} not found in psi={}", drb_to_mod.drb_id, session.pdu_session_id);
       pdu_session_result.drb_setup_results.push_back(drb_result);
       continue;
     }
@@ -297,13 +297,13 @@ pdu_session_manager_impl::modify_pdu_session(const e1ap_pdu_session_res_to_modif
     auto& drb = drb_iter->second;
     if (new_tnl_info_required) {
       if (not f1u_teid_allocator.release_teid(drb->f1u_ul_teid)) {
-        logger.error("ue={} could not free old ul_teid={}", ue_index, drb->f1u_ul_teid);
+        logger.log_error("Could not free old ul_teid={}", drb->f1u_ul_teid);
       }
 
       // Allocate new UL TEID for DRB
       expected<gtpu_teid_t> ret = f1u_teid_allocator.request_teid();
       if (not ret.has_value()) {
-        logger.error("ue={} could not allocate ul_teid", ue_index);
+        logger.log_error("Could not allocate ul_teid");
         continue;
       }
       drb->f1u_ul_teid = ret.value();
@@ -359,12 +359,12 @@ pdu_session_manager_impl::modify_pdu_session(const e1ap_pdu_session_res_to_modif
                                      : security::ciphering_enabled::on);
     }
 
-    logger.info("Modified {}, psi={}, f1u_teid={}.", drb_to_mod.drb_id, session.pdu_session_id, drb->f1u_ul_teid);
+    logger.log_info("Modified {}. psi={} f1u_teid={}", drb_to_mod.drb_id, session.pdu_session_id, drb->f1u_ul_teid);
 
     // Apply QoS flows
     for (auto& qos_flow_info : drb_to_mod.flow_map_info) {
       // TODO
-      logger.warning("Unsupported modification of QoS flow. qos_flow_id={}", qos_flow_info.qos_flow_id);
+      logger.log_warning("Unsupported modification of QoS flow for {}", qos_flow_info.qos_flow_id);
     }
 
     // Add result
@@ -380,22 +380,22 @@ pdu_session_manager_impl::modify_pdu_session(const e1ap_pdu_session_res_to_modif
     // find DRB in PDU session
     auto drb_iter = pdu_session->drbs.find(drb_to_rem);
     if (drb_iter == pdu_session->drbs.end()) {
-      logger.warning("Cannot remove DRB: drb_id={} not found in pdu_session_id={}", drb_to_rem, session.pdu_session_id);
+      logger.log_warning("Cannot remove {}. DRB not found in psi={}", drb_to_rem, session.pdu_session_id);
       continue;
     }
     srsran_assert(drb_to_rem == drb_iter->second->drb_id,
-                  "Query for drb_id={} in pdu_session_id={} provided different drb_id={}",
+                  "Query for {} in psi={} provided different drb_id={}",
                   drb_to_rem,
                   session.pdu_session_id,
                   drb_iter->second->drb_id);
 
     // remove DRB (this will automatically disconnect from F1-U gateway)
     if (not f1u_teid_allocator.release_teid(drb_iter->second->f1u_ul_teid)) {
-      logger.error("ue={} psi={} drb_id={} could not free ul_teid={}", ue_index, session.pdu_session_id, drb_to_rem);
+      logger.log_error("psi={} drb_id={} could not free ul_teid={}", session.pdu_session_id, drb_to_rem);
     }
     pdu_session->drbs.erase(drb_iter);
 
-    logger.info("Removed DRB. drb_id={}, pdu_session_id={}.", drb_to_rem, session.pdu_session_id);
+    logger.log_info("Removed {} for psi={}", drb_to_rem, session.pdu_session_id);
   }
 
   pdu_session_result.success = true;
@@ -405,28 +405,27 @@ pdu_session_manager_impl::modify_pdu_session(const e1ap_pdu_session_res_to_modif
 void pdu_session_manager_impl::remove_pdu_session(pdu_session_id_t pdu_session_id)
 {
   if (pdu_sessions.find(pdu_session_id) == pdu_sessions.end()) {
-    logger.error("PDU session {} not found", pdu_session_id);
+    logger.log_error("PDU session {} not found", pdu_session_id);
     return;
   }
 
   // Disconnect all UL tunnels for this PDU session.
   auto& pdu_session = pdu_sessions.at(pdu_session_id);
   for (const auto& drb : pdu_session->drbs) {
-    logger.debug("Disconnecting CU bearer with UL-TEID={}", drb.second->f1u_ul_teid);
+    logger.log_debug("Disconnecting CU bearer with UL-TEID={}", drb.second->f1u_ul_teid);
     up_transport_layer_info f1u_ul_tunnel_addr;
     f1u_ul_tunnel_addr.tp_address.from_string(net_config.f1u_bind_addr);
     f1u_ul_tunnel_addr.gtp_teid = drb.second->f1u_ul_teid;
     f1u_gw.disconnect_cu_bearer(f1u_ul_tunnel_addr);
     if (f1u_teid_allocator.release_teid(drb.second->f1u_ul_teid)) {
-      logger.error("ue={} psi={} could not remove ul_teid at session termination. ul_teid={}",
-                   ue_index,
-                   pdu_session_id,
-                   drb.second->f1u_ul_teid);
+      logger.log_error("psi={} could not remove ul_teid at session termination. ul_teid={}",
+                       pdu_session_id,
+                       drb.second->f1u_ul_teid);
     }
   }
 
   pdu_sessions.erase(pdu_session_id);
-  logger.info("Removing PDU session {}", pdu_session_id);
+  logger.log_info("Removing PDU session with psi={}", pdu_session_id);
 }
 
 size_t pdu_session_manager_impl::get_nof_pdu_sessions()

lib/cu_up/pdu_session_manager_impl.h

@@ -10,6 +10,7 @@
 
 #pragma once
 
+#include "cu_up_ue_logger.h"
 #include "pdu_session.h"
 #include "pdu_session_manager.h"
 #include "srsran/cu_up/cu_up_configuration.h"
@@ -33,7 +34,7 @@ class pdu_session_manager_impl final : public pdu_session_manager_ctrl
                            const security::sec_as_config&       security_info_,
                            network_interface_config&            net_config_,
                            n3_interface_config&                 n3_config_,
-                           srslog::basic_logger&                logger_,
+                           cu_up_ue_logger&                     logger_,
                            unique_timer&                        ue_inactivity_timer,
                            timer_factory                        timers_,
                            f1u_cu_up_gateway&                   f1u_gw_,
@@ -64,7 +65,7 @@ class pdu_session_manager_impl final : public pdu_session_manager_ctrl
   const security::sec_as_config&                           security_info;
   network_interface_config&                                net_config;
   n3_interface_config&                                     n3_config;
-  srslog::basic_logger&                                    logger;
+  cu_up_ue_logger&                                         logger;
   unique_timer&                                            ue_inactivity_timer;
   timer_factory                                            timers;
   gtpu_tunnel_tx_upper_layer_notifier&                     gtpu_tx_notifier;