diff --git a/lib/include/srslte/upper/rlc.h b/lib/include/srslte/upper/rlc.h index ffa576965..ea868d21a 100644 --- a/lib/include/srslte/upper/rlc.h +++ b/lib/include/srslte/upper/rlc.h @@ -86,7 +86,7 @@ private: void reset_metrics(); byte_buffer_pool* pool = nullptr; - srslte::log_ref rlc_log; + srslog::basic_logger& logger; srsue::pdcp_interface_rlc* pdcp = nullptr; srsue::rrc_interface_rlc* rrc = nullptr; srslte::timer_handler* timers = nullptr; diff --git a/lib/include/srslte/upper/rlc_am_lte.h b/lib/include/srslte/upper/rlc_am_lte.h index 3e715d282..efb33f558 100644 --- a/lib/include/srslte/upper/rlc_am_lte.h +++ b/lib/include/srslte/upper/rlc_am_lte.h @@ -69,7 +69,7 @@ struct pdcp_sdu_info_t { class rlc_am_lte : public rlc_common { public: - rlc_am_lte(srslte::log_ref log_, + rlc_am_lte(srslog::basic_logger& logger, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_, @@ -146,9 +146,9 @@ private: bool poll_required(); bool do_status(); - rlc_am_lte* parent = nullptr; - byte_buffer_pool* pool = nullptr; - srslte::log_ref log; + rlc_am_lte* parent = nullptr; + byte_buffer_pool* pool = nullptr; + srslog::basic_logger& logger; /**************************************************************************** * Configurable parameters @@ -237,9 +237,9 @@ private: void print_rx_segments(); bool add_segment_and_check(rlc_amd_rx_pdu_segments_t* pdu, rlc_amd_rx_pdu_t* segment); - rlc_am_lte* parent = nullptr; - byte_buffer_pool* pool = nullptr; - srslte::log_ref log; + rlc_am_lte* parent = nullptr; + byte_buffer_pool* pool = nullptr; + srslog::basic_logger& logger; /**************************************************************************** * Configurable parameters @@ -284,7 +284,7 @@ private: // Common variables needed/provided by parent class srsue::rrc_interface_rlc* rrc = nullptr; - srslte::log_ref log; + srslog::basic_logger& logger; srsue::pdcp_interface_rlc* pdcp = nullptr; srslte::timer_handler* timers = nullptr; uint32_t lcid = 0; diff --git a/lib/include/srslte/upper/rlc_common.h b/lib/include/srslte/upper/rlc_common.h index dd721631f..fcc19a59a 100644 --- a/lib/include/srslte/upper/rlc_common.h +++ b/lib/include/srslte/upper/rlc_common.h @@ -282,7 +282,7 @@ private: // Do not block ever if (!rx_pdu_resume_queue.try_push(p)) { - srslte::logmap::get("RLC ")->warning("Dropping SDUs while bearer suspended.\n"); + srslog::fetch_basic_logger("RLC").warning("Dropping SDUs while bearer suspended."); return; } } @@ -292,7 +292,7 @@ private: { // Do not block ever if (not tx_sdu_resume_queue.try_push(std::move(sdu))) { - srslte::logmap::get("RLC ")->warning("Dropping SDUs while bearer suspended.\n"); + srslog::fetch_basic_logger("RLC").warning("Dropping SDUs while bearer suspended."); return; } } diff --git a/lib/include/srslte/upper/rlc_tm.h b/lib/include/srslte/upper/rlc_tm.h index 2b159aa67..4c23ef6aa 100644 --- a/lib/include/srslte/upper/rlc_tm.h +++ b/lib/include/srslte/upper/rlc_tm.h @@ -25,7 +25,10 @@ namespace srslte { class rlc_tm final : public rlc_common { public: - rlc_tm(srslte::log_ref log_, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_); + rlc_tm(srslog::basic_logger& logger, + uint32_t lcid_, + srsue::pdcp_interface_rlc* pdcp_, + srsue::rrc_interface_rlc* rrc_); ~rlc_tm() override; bool configure(const rlc_config_t& cnfg) override; void stop() override; @@ -53,7 +56,7 @@ public: private: byte_buffer_pool* pool = nullptr; - srslte::log_ref log; + srslog::basic_logger& logger; uint32_t lcid = 0; srsue::pdcp_interface_rlc* pdcp = nullptr; srsue::rrc_interface_rlc* rrc = nullptr; diff --git a/lib/include/srslte/upper/rlc_um_base.h b/lib/include/srslte/upper/rlc_um_base.h index fd5f64371..115d1ad9e 100644 --- a/lib/include/srslte/upper/rlc_um_base.h +++ b/lib/include/srslte/upper/rlc_um_base.h @@ -30,7 +30,7 @@ namespace srslte { class rlc_um_base : public rlc_common { public: - rlc_um_base(srslte::log_ref log_, + rlc_um_base(srslog::basic_logger& logger, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_, @@ -82,10 +82,10 @@ protected: virtual uint32_t get_buffer_state() = 0; protected: - byte_buffer_pool* pool = nullptr; - srslte::log_ref log; - std::string rb_name; - rlc_um_base* parent = nullptr; + byte_buffer_pool* pool = nullptr; + srslog::basic_logger& logger; + std::string rb_name; + rlc_um_base* parent = nullptr; rlc_config_t cfg = {}; @@ -111,7 +111,6 @@ protected: // Receiver sub-class base class rlc_um_base_rx : public timer_callback { - public: rlc_um_base_rx(rlc_um_base* parent_); virtual ~rlc_um_base_rx(); @@ -124,7 +123,7 @@ protected: protected: byte_buffer_pool* pool = nullptr; - srslte::log_ref log; + srslog::basic_logger& logger; srslte::timer_handler* timers = nullptr; srsue::pdcp_interface_rlc* pdcp = nullptr; srsue::rrc_interface_rlc* rrc = nullptr; @@ -145,7 +144,7 @@ protected: // Common variables needed by parent class srsue::rrc_interface_rlc* rrc = nullptr; srsue::pdcp_interface_rlc* pdcp = nullptr; - srslte::log_ref log; + srslog::basic_logger& logger; srslte::timer_handler* timers = nullptr; uint32_t lcid = 0; rlc_config_t cfg = {}; diff --git a/lib/include/srslte/upper/rlc_um_lte.h b/lib/include/srslte/upper/rlc_um_lte.h index 7016e163d..514be93af 100644 --- a/lib/include/srslte/upper/rlc_um_lte.h +++ b/lib/include/srslte/upper/rlc_um_lte.h @@ -34,7 +34,7 @@ typedef struct { class rlc_um_lte : public rlc_um_base { public: - rlc_um_lte(srslte::log_ref log_, + rlc_um_lte(srslog::basic_logger& logger, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_, diff --git a/lib/include/srslte/upper/rlc_um_nr.h b/lib/include/srslte/upper/rlc_um_nr.h index a3563cd0b..d2ecf4a5e 100644 --- a/lib/include/srslte/upper/rlc_um_nr.h +++ b/lib/include/srslte/upper/rlc_um_nr.h @@ -34,7 +34,7 @@ typedef struct { class rlc_um_nr : public rlc_um_base { public: - rlc_um_nr(srslte::log_ref log_, + rlc_um_nr(srslog::basic_logger& logger, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_, diff --git a/lib/src/upper/rlc.cc b/lib/src/upper/rlc.cc index 38375a2ca..f51cff034 100644 --- a/lib/src/upper/rlc.cc +++ b/lib/src/upper/rlc.cc @@ -19,7 +19,7 @@ namespace srslte { -rlc::rlc(const char* logname) : rlc_log(logname) +rlc::rlc(const char* logname) : logger(srslog::fetch_basic_logger(logname)) { pool = byte_buffer_pool::get_instance(); pthread_rwlock_init(&rwlock, NULL); @@ -109,21 +109,21 @@ void rlc::get_metrics(rlc_metrics_t& m, const uint32_t nof_tti) double rx_rate_mbps = (nof_tti > 0) ? ((metrics.num_rx_pdu_bytes * 8 / (double)1e6) / (nof_tti / 1000.0)) : 0.0; double tx_rate_mbps = (nof_tti > 0) ? ((metrics.num_tx_pdu_bytes * 8 / (double)1e6) / (nof_tti / 1000.0)) : 0.0; - rlc_log->info("lcid=%d, rx_rate_mbps=%4.2f (real=%4.2f), tx_rate_mbps=%4.2f (real=%4.2f)\n", - it->first, - rx_rate_mbps, - rx_rate_mbps_real_time, - tx_rate_mbps, - tx_rate_mbps_real_time); + logger.info("lcid=%d, rx_rate_mbps=%4.2f (real=%4.2f), tx_rate_mbps=%4.2f (real=%4.2f)", + it->first, + rx_rate_mbps, + rx_rate_mbps_real_time, + tx_rate_mbps, + tx_rate_mbps_real_time); m.bearer[it->first] = metrics; } // Add multicast metrics for (rlc_map_t::iterator it = rlc_array_mrb.begin(); it != rlc_array_mrb.end(); ++it) { rlc_bearer_metrics_t metrics = it->second->get_metrics(); - rlc_log->info("MCH_LCID=%d, rx_rate_mbps=%4.2f\n", - it->first, - (metrics.num_rx_pdu_bytes * 8 / static_cast(1e6)) / secs.count()); + logger.info("MCH_LCID=%d, rx_rate_mbps=%4.2f", + it->first, + (metrics.num_rx_pdu_bytes * 8 / static_cast(1e6)) / secs.count()); m.bearer[it->first] = metrics; } @@ -148,10 +148,10 @@ void rlc::reestablish() void rlc::reestablish(uint32_t lcid) { if (valid_lcid(lcid)) { - rlc_log->info("Reestablishing %s\n", rrc->get_rb_name(lcid).c_str()); + logger.info("Reestablishing %s", rrc->get_rb_name(lcid).c_str()); rlc_array.at(lcid)->reestablish(); } else { - rlc_log->warning("RLC LCID %d doesn't exist.\n", lcid); + logger.warning("RLC LCID %d doesn't exist.", lcid); } } @@ -191,7 +191,7 @@ void rlc::write_sdu(uint32_t lcid, unique_byte_buffer_t sdu) { // TODO: rework build PDU logic to allow large SDUs (without concatenation) if (sdu->N_bytes > RLC_MAX_SDU_SIZE) { - rlc_log->warning("Dropping too long SDU of size %d B (Max. size %d B).\n", sdu->N_bytes, RLC_MAX_SDU_SIZE); + logger.warning("Dropping too long SDU of size %d B (Max. size %d B).", sdu->N_bytes, RLC_MAX_SDU_SIZE); return; } @@ -199,7 +199,7 @@ void rlc::write_sdu(uint32_t lcid, unique_byte_buffer_t sdu) rlc_array.at(lcid)->write_sdu_s(std::move(sdu)); update_bsr(lcid); } else { - rlc_log->warning("RLC LCID %d doesn't exist. Deallocating SDU\n", lcid); + logger.warning("RLC LCID %d doesn't exist. Deallocating SDU", lcid); } } @@ -209,7 +209,7 @@ void rlc::write_sdu_mch(uint32_t lcid, unique_byte_buffer_t sdu) rlc_array_mrb.at(lcid)->write_sdu(std::move(sdu)); update_bsr_mch(lcid); } else { - rlc_log->warning("RLC LCID %d doesn't exist. Deallocating SDU\n", lcid); + logger.warning("RLC LCID %d doesn't exist. Deallocating SDU", lcid); } } @@ -220,7 +220,7 @@ bool rlc::rb_is_um(uint32_t lcid) if (valid_lcid(lcid)) { ret = rlc_array.at(lcid)->get_mode() == rlc_mode_t::um; } else { - rlc_log->warning("LCID %d doesn't exist.\n", lcid); + logger.warning("LCID %d doesn't exist.", lcid); } return ret; @@ -232,7 +232,7 @@ void rlc::discard_sdu(uint32_t lcid, uint32_t discard_sn) rlc_array.at(lcid)->discard_sdu(discard_sn); update_bsr(lcid); } else { - rlc_log->warning("RLC LCID %d doesn't exist. Ignoring discard SDU\n", lcid); + logger.warning("RLC LCID %d doesn't exist. Ignoring discard SDU", lcid); } } @@ -241,7 +241,7 @@ bool rlc::sdu_queue_is_full(uint32_t lcid) if (valid_lcid(lcid)) { return rlc_array.at(lcid)->sdu_queue_is_full(); } - rlc_log->warning("RLC LCID %d doesn't exist. Ignoring queue check\n", lcid); + logger.warning("RLC LCID %d doesn't exist. Ignoring queue check", lcid); return false; } @@ -291,7 +291,7 @@ int rlc::read_pdu(uint32_t lcid, uint8_t* payload, uint32_t nof_bytes) ret = rlc_array.at(lcid)->read_pdu(payload, nof_bytes); update_bsr(lcid); } else { - rlc_log->warning("LCID %d doesn't exist.\n", lcid); + logger.warning("LCID %d doesn't exist.", lcid); } return ret; @@ -306,7 +306,7 @@ int rlc::read_pdu_mch(uint32_t lcid, uint8_t* payload, uint32_t nof_bytes) ret = rlc_array_mrb.at(lcid)->read_pdu(payload, nof_bytes); update_bsr_mch(lcid); } else { - rlc_log->warning("LCID %d doesn't exist.\n", lcid); + logger.warning("LCID %d doesn't exist.", lcid); } return ret; @@ -319,21 +319,21 @@ void rlc::write_pdu(uint32_t lcid, uint8_t* payload, uint32_t nof_bytes) rlc_array.at(lcid)->write_pdu_s(payload, nof_bytes); update_bsr(lcid); } else { - rlc_log->warning("LCID %d doesn't exist. Dropping PDU.\n", lcid); + logger.warning("LCID %d doesn't exist. Dropping PDU.", lcid); } } // Pass directly to PDCP, no DL througput counting done void rlc::write_pdu_bcch_bch(srslte::unique_byte_buffer_t pdu) { - rlc_log->info_hex(pdu->msg, pdu->N_bytes, "BCCH BCH message received."); + logger.info(pdu->msg, pdu->N_bytes, "BCCH BCH message received."); pdcp->write_pdu_bcch_bch(std::move(pdu)); } // Pass directly to PDCP, no DL througput counting done void rlc::write_pdu_bcch_dlsch(uint8_t* payload, uint32_t nof_bytes) { - rlc_log->info_hex(payload, nof_bytes, "BCCH TXSCH message received."); + logger.info(payload, nof_bytes, "BCCH TXSCH message received."); unique_byte_buffer_t buf = make_byte_buffer(); if (buf != NULL) { memcpy(buf->msg, payload, nof_bytes); @@ -341,14 +341,14 @@ void rlc::write_pdu_bcch_dlsch(uint8_t* payload, uint32_t nof_bytes) buf->set_timestamp(); pdcp->write_pdu_bcch_dlsch(std::move(buf)); } else { - rlc_log->error("Fatal error: Out of buffers from the pool in write_pdu_bcch_dlsch()\n"); + logger.error("Fatal error: Out of buffers from the pool in write_pdu_bcch_dlsch()"); } } // Pass directly to PDCP, no DL througput counting done void rlc::write_pdu_pcch(srslte::unique_byte_buffer_t pdu) { - rlc_log->info_hex(pdu->msg, pdu->N_bytes, "PCCH message received."); + logger.info(pdu->msg, pdu->N_bytes, "PCCH message received."); pdcp->write_pdu_pcch(std::move(pdu)); } @@ -393,7 +393,7 @@ void rlc::add_bearer(uint32_t lcid, const rlc_config_t& cnfg) if (cnfg.rlc_mode != rlc_mode_t::tm and rlc_array.find(lcid) != rlc_array.end()) { if (rlc_array[lcid]->get_mode() != cnfg.rlc_mode) { - rlc_log->info("Switching RLC entity type. Recreating it.\n"); + logger.info("Switching RLC entity type. Recreating it."); rlc_array.erase(lcid); } } @@ -402,16 +402,16 @@ void rlc::add_bearer(uint32_t lcid, const rlc_config_t& cnfg) if (cnfg.rat == srslte_rat_t::lte) { switch (cnfg.rlc_mode) { case rlc_mode_t::tm: - rlc_entity = new rlc_tm(rlc_log, lcid, pdcp, rrc); + rlc_entity = new rlc_tm(logger, lcid, pdcp, rrc); break; case rlc_mode_t::am: - rlc_entity = new rlc_am_lte(rlc_log, lcid, pdcp, rrc, timers); + rlc_entity = new rlc_am_lte(logger, lcid, pdcp, rrc, timers); break; case rlc_mode_t::um: - rlc_entity = new rlc_um_lte(rlc_log, lcid, pdcp, rrc, timers); + rlc_entity = new rlc_um_lte(logger, lcid, pdcp, rrc, timers); break; default: - rlc_log->error("Cannot add RLC entity - invalid mode\n"); + logger.error("Cannot add RLC entity - invalid mode"); return; } if (rlc_entity != nullptr) { @@ -421,38 +421,38 @@ void rlc::add_bearer(uint32_t lcid, const rlc_config_t& cnfg) } else if (cnfg.rat == srslte_rat_t::nr) { switch (cnfg.rlc_mode) { case rlc_mode_t::tm: - rlc_entity = new rlc_tm(rlc_log, lcid, pdcp, rrc); + rlc_entity = new rlc_tm(logger, lcid, pdcp, rrc); break; case rlc_mode_t::um: - rlc_entity = new rlc_um_nr(rlc_log, lcid, pdcp, rrc, timers); + rlc_entity = new rlc_um_nr(logger, lcid, pdcp, rrc, timers); break; default: - rlc_log->error("Cannot add RLC entity - invalid mode\n"); + logger.error("Cannot add RLC entity - invalid mode"); return; } #endif } else { - rlc_log->error("RAT not supported\n"); + logger.error("RAT not supported"); return; } if (not rlc_array.insert(rlc_map_pair_t(lcid, rlc_entity)).second) { - rlc_log->error("Error inserting RLC entity in to array\n."); + logger.error("Error inserting RLC entity in to array."); goto delete_and_exit; } - rlc_log->info("Added radio bearer %s in %s\n", rrc->get_rb_name(lcid).c_str(), to_string(cnfg.rlc_mode).c_str()); + logger.info("Added radio bearer %s in %s", rrc->get_rb_name(lcid).c_str(), to_string(cnfg.rlc_mode).c_str()); rlc_entity = NULL; } // configure and add to array if (cnfg.rlc_mode != rlc_mode_t::tm and rlc_array.find(lcid) != rlc_array.end()) { if (not rlc_array.at(lcid)->configure(cnfg)) { - rlc_log->error("Error configuring RLC entity\n."); + logger.error("Error configuring RLC entity."); goto delete_and_exit; } } - rlc_log->info("Configured radio bearer %s in %s\n", rrc->get_rb_name(lcid).c_str(), to_string(cnfg.rlc_mode).c_str()); + logger.info("Configured radio bearer %s in %s", rrc->get_rb_name(lcid).c_str(), to_string(cnfg.rlc_mode).c_str()); delete_and_exit: if (rlc_entity) { @@ -466,22 +466,22 @@ void rlc::add_bearer_mrb(uint32_t lcid) rlc_common* rlc_entity = NULL; if (not valid_lcid_mrb(lcid)) { - rlc_entity = new rlc_um_lte(rlc_log, lcid, pdcp, rrc, timers); + rlc_entity = new rlc_um_lte(logger, lcid, pdcp, rrc, timers); // configure and add to array if (not rlc_entity->configure(rlc_config_t::mch_config())) { - rlc_log->error("Error configuring RLC entity\n."); + logger.error("Error configuring RLC entity."); goto delete_and_exit; } if (rlc_array_mrb.count(lcid) == 0) { if (not rlc_array_mrb.insert(rlc_map_pair_t(lcid, rlc_entity)).second) { - rlc_log->error("Error inserting RLC entity in to array\n."); + logger.error("Error inserting RLC entity in to array."); goto delete_and_exit; } } - rlc_log->warning("Added bearer MRB%d with mode RLC_UM\n", lcid); + logger.warning("Added bearer MRB%d with mode RLC_UM", lcid); return; } else { - rlc_log->warning("Bearer MRB%d already created.\n", lcid); + logger.warning("Bearer MRB%d already created.", lcid); } delete_and_exit: @@ -499,9 +499,9 @@ void rlc::del_bearer(uint32_t lcid) it->second->stop(); delete (it->second); rlc_array.erase(it); - rlc_log->warning("Deleted RLC bearer %s\n", rrc->get_rb_name(lcid).c_str()); + logger.warning("Deleted RLC bearer %s", rrc->get_rb_name(lcid).c_str()); } else { - rlc_log->error("Can't delete bearer %s. Bearer doesn't exist.\n", rrc->get_rb_name(lcid).c_str()); + logger.error("Can't delete bearer %s. Bearer doesn't exist.", rrc->get_rb_name(lcid).c_str()); } } @@ -514,9 +514,9 @@ void rlc::del_bearer_mrb(uint32_t lcid) it->second->stop(); delete (it->second); rlc_array_mrb.erase(it); - rlc_log->warning("Deleted RLC MRB bearer %s\n", rrc->get_rb_name(lcid).c_str()); + logger.warning("Deleted RLC MRB bearer %s", rrc->get_rb_name(lcid).c_str()); } else { - rlc_log->error("Can't delete bearer %s. Bearer doesn't exist.\n", rrc->get_rb_name(lcid).c_str()); + logger.error("Can't delete bearer %s. Bearer doesn't exist.", rrc->get_rb_name(lcid).c_str()); } } @@ -530,22 +530,22 @@ void rlc::change_lcid(uint32_t old_lcid, uint32_t new_lcid) rlc_map_t::iterator it = rlc_array.find(old_lcid); rlc_common* rlc_entity = it->second; if (not rlc_array.insert(rlc_map_pair_t(new_lcid, rlc_entity)).second) { - rlc_log->error("Error inserting RLC entity into array\n."); + logger.error("Error inserting RLC entity into array."); return; } // erase from old position rlc_array.erase(it); if (valid_lcid(new_lcid) && not valid_lcid(old_lcid)) { - rlc_log->info("Successfully changed LCID of RLC bearer from %d to %d\n", old_lcid, new_lcid); + logger.info("Successfully changed LCID of RLC bearer from %d to %d", old_lcid, new_lcid); } else { - rlc_log->error("Error during LCID change of RLC bearer from %d to %d\n", old_lcid, new_lcid); + logger.error("Error during LCID change of RLC bearer from %d to %d", old_lcid, new_lcid); } } else { - rlc_log->error("Can't change LCID of bearer %s from %d to %d. Bearer doesn't exist or new LCID already occupied.\n", - rrc->get_rb_name(old_lcid).c_str(), - old_lcid, - new_lcid); + logger.error("Can't change LCID of bearer %s from %d to %d. Bearer doesn't exist or new LCID already occupied.", + rrc->get_rb_name(old_lcid).c_str(), + old_lcid, + new_lcid); } } @@ -554,26 +554,26 @@ void rlc::suspend_bearer(uint32_t lcid) { if (valid_lcid(lcid)) { if (rlc_array.at(lcid)->suspend()) { - rlc_log->info("Suspended radio bearer %s\n", rrc->get_rb_name(lcid).c_str()); + logger.info("Suspended radio bearer %s", rrc->get_rb_name(lcid).c_str()); } else { - rlc_log->error("Error suspending RLC entity: bearer already suspended\n."); + logger.error("Error suspending RLC entity: bearer already suspended."); } } else { - rlc_log->error("Suspending bearer: bearer %s not configured.\n", rrc->get_rb_name(lcid).c_str()); + logger.error("Suspending bearer: bearer %s not configured.", rrc->get_rb_name(lcid).c_str()); } } void rlc::resume_bearer(uint32_t lcid) { - rlc_log->info("Resuming radio bearer %s\n", rrc->get_rb_name(lcid).c_str()); + logger.info("Resuming radio bearer %s", rrc->get_rb_name(lcid).c_str()); if (valid_lcid(lcid)) { if (rlc_array.at(lcid)->resume()) { - rlc_log->info("Resumed radio bearer %s\n", rrc->get_rb_name(lcid).c_str()); + logger.info("Resumed radio bearer %s", rrc->get_rb_name(lcid).c_str()); } else { - rlc_log->error("Error resuming RLC entity: bearer not suspended\n."); + logger.error("Error resuming RLC entity: bearer not suspended."); } } else { - rlc_log->error("Resuming bearer: bearer %s not configured.\n", rrc->get_rb_name(lcid).c_str()); + logger.error("Resuming bearer: bearer %s not configured.", rrc->get_rb_name(lcid).c_str()); } } @@ -589,7 +589,7 @@ bool rlc::has_bearer(uint32_t lcid) bool rlc::valid_lcid(uint32_t lcid) { if (lcid >= SRSLTE_N_RADIO_BEARERS) { - rlc_log->error("Radio bearer id must be in [0:%d] - %d\n", SRSLTE_N_RADIO_BEARERS, lcid); + logger.error("Radio bearer id must be in [0:%d] - %d", SRSLTE_N_RADIO_BEARERS, lcid); return false; } @@ -603,7 +603,7 @@ bool rlc::valid_lcid(uint32_t lcid) bool rlc::valid_lcid_mrb(uint32_t lcid) { if (lcid >= SRSLTE_N_MCH_LCIDS) { - rlc_log->error("Radio bearer id must be in [0:%d] - %d\n", SRSLTE_N_RADIO_BEARERS, lcid); + logger.error("Radio bearer id must be in [0:%d] - %d", SRSLTE_N_RADIO_BEARERS, lcid); return false; } diff --git a/lib/src/upper/rlc_am_lte.cc b/lib/src/upper/rlc_am_lte.cc index 33f2f4312..825542cf4 100644 --- a/lib/src/upper/rlc_am_lte.cc +++ b/lib/src/upper/rlc_am_lte.cc @@ -23,12 +23,12 @@ namespace srslte { -rlc_am_lte::rlc_am_lte(srslte::log_ref log_, +rlc_am_lte::rlc_am_lte(srslog::basic_logger& logger, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_, srslte::timer_handler* timers_) : - log(log_), rrc(rrc_), pdcp(pdcp_), timers(timers_), lcid(lcid_), tx(this), rx(this) + logger(logger), rrc(rrc_), pdcp(pdcp_), timers(timers_), lcid(lcid_), tx(this), rx(this) {} // Applies new configuration. Must be just reestablished or initiated @@ -41,24 +41,24 @@ bool rlc_am_lte::configure(const rlc_config_t& cfg_) cfg = cfg_; if (not rx.configure(cfg.am)) { - log->error("Error configuring bearer (RX)\n"); + logger.error("Error configuring bearer (RX)"); return false; } if (not tx.configure(cfg)) { - log->error("Error configuring bearer (TX)\n"); + logger.error("Error configuring bearer (TX)"); return false; } - log->info("%s configured: t_poll_retx=%d, poll_pdu=%d, poll_byte=%d, max_retx_thresh=%d, " - "t_reordering=%d, t_status_prohibit=%d\n", - rb_name.c_str(), - cfg.am.t_poll_retx, - cfg.am.poll_pdu, - cfg.am.poll_byte, - cfg.am.max_retx_thresh, - cfg.am.t_reordering, - cfg.am.t_status_prohibit); + logger.info("%s configured: t_poll_retx=%d, poll_pdu=%d, poll_byte=%d, max_retx_thresh=%d, " + "t_reordering=%d, t_status_prohibit=%d", + rb_name.c_str(), + cfg.am.t_poll_retx, + cfg.am.poll_pdu, + cfg.am.poll_byte, + cfg.am.max_retx_thresh, + cfg.am.t_reordering, + cfg.am.t_status_prohibit); return true; } @@ -75,14 +75,14 @@ void rlc_am_lte::empty_queue() void rlc_am_lte::reestablish() { - log->debug("Reestablished bearer %s\n", rb_name.c_str()); + logger.debug("Reestablished bearer %s", rb_name.c_str()); tx.reestablish(); // calls stop and enables tx again rx.reestablish(); // calls only stop } void rlc_am_lte::stop() { - log->debug("Stopped bearer %s\n", rb_name.c_str()); + logger.debug("Stopped bearer %s", rb_name.c_str()); tx.stop(); rx.stop(); } @@ -167,7 +167,7 @@ void rlc_am_lte::write_pdu(uint8_t* payload, uint32_t nof_bytes) rlc_am_lte::rlc_am_lte_tx::rlc_am_lte_tx(rlc_am_lte* parent_) : parent(parent_), - log(parent_->log), + logger(parent_->logger), pool(byte_buffer_pool::get_instance()), poll_retx_timer(parent_->timers->get_unique_timer()), status_prohibit_timer(parent_->timers->get_unique_timer()) @@ -192,7 +192,7 @@ bool rlc_am_lte::rlc_am_lte_tx::configure(const rlc_config_t& cfg_) // check timers if (not poll_retx_timer.is_valid() or not status_prohibit_timer.is_valid()) { - log->error("Configuring RLC AM TX: timers not configured\n"); + logger.error("Configuring RLC AM TX: timers not configured"); return false; } @@ -286,36 +286,36 @@ uint32_t rlc_am_lte::rlc_am_lte_tx::get_buffer_state() uint32_t n_bytes = 0; uint32_t n_sdus = 0; - log->debug("%s Buffer state - do_status=%s, status_prohibit_running=%s (%d/%d)\n", - RB_NAME, - do_status() ? "yes" : "no", - status_prohibit_timer.is_running() ? "yes" : "no", - status_prohibit_timer.time_elapsed(), - status_prohibit_timer.duration()); + logger.debug("%s Buffer state - do_status=%s, status_prohibit_running=%s (%d/%d)", + RB_NAME, + do_status() ? "yes" : "no", + status_prohibit_timer.is_running() ? "yes" : "no", + status_prohibit_timer.time_elapsed(), + status_prohibit_timer.duration()); // Bytes needed for status report if (do_status() && not status_prohibit_timer.is_running()) { n_bytes += parent->rx.get_status_pdu_length(); - log->debug("%s Buffer state - total status report: %d bytes\n", RB_NAME, n_bytes); + logger.debug("%s Buffer state - total status report: %d bytes", RB_NAME, n_bytes); } // Bytes needed for retx if (not retx_queue.empty()) { rlc_amd_retx_t retx = retx_queue.front(); - log->debug("%s Buffer state - retx - SN=%d, Segment: %s, %d:%d\n", - RB_NAME, - retx.sn, - retx.is_segment ? "true" : "false", - retx.so_start, - retx.so_end); + logger.debug("%s Buffer state - retx - SN=%d, Segment: %s, %d:%d", + RB_NAME, + retx.sn, + retx.is_segment ? "true" : "false", + retx.so_start, + retx.so_end); if (tx_window.end() != tx_window.find(retx.sn)) { int req_bytes = required_buffer_size(retx); if (req_bytes < 0) { - log->error("In get_buffer_state(): Removing retx.sn=%d from queue\n", retx.sn); + logger.error("In get_buffer_state(): Removing retx.sn=%d from queue", retx.sn); retx_queue.pop_front(); } else { n_bytes += req_bytes; - log->debug("Buffer state - retx: %d bytes\n", n_bytes); + logger.debug("Buffer state - retx: %d bytes", n_bytes); } } } @@ -338,7 +338,7 @@ uint32_t rlc_am_lte::rlc_am_lte_tx::get_buffer_state() // Room needed for fixed header of data PDUs if (n_bytes > 0 && n_sdus > 0) { n_bytes += 2; // Two bytes for fixed header with SN length = 10 - log->debug("%s Total buffer state - %d SDUs (%d B)\n", RB_NAME, n_sdus, n_bytes); + logger.debug("%s Total buffer state - %d SDUs (%d B)", RB_NAME, n_sdus, n_bytes); } pthread_mutex_unlock(&mutex); @@ -355,7 +355,7 @@ int rlc_am_lte::rlc_am_lte_tx::write_sdu(unique_byte_buffer_t sdu) } if (sdu.get() == nullptr) { - log->warning("NULL SDU pointer in write_sdu()\n"); + logger.warning("NULL SDU pointer in write_sdu()"); pthread_mutex_unlock(&mutex); return SRSLTE_ERROR; } @@ -369,16 +369,15 @@ int rlc_am_lte::rlc_am_lte_tx::write_sdu(unique_byte_buffer_t sdu) uint32_t nof_bytes = sdu->N_bytes; srslte::error_type ret = tx_sdu_queue.try_write(std::move(sdu)); if (ret) { - log->info_hex( - msg_ptr, nof_bytes, "%s Tx SDU (%d B, tx_sdu_queue_len=%d)\n", RB_NAME, nof_bytes, tx_sdu_queue.size()); + logger.info(msg_ptr, nof_bytes, "%s Tx SDU (%d B, tx_sdu_queue_len=%d)", RB_NAME, nof_bytes, tx_sdu_queue.size()); } else { // in case of fail, the try_write returns back the sdu - log->warning_hex(ret.error()->msg, - ret.error()->N_bytes, - "[Dropped SDU] %s Tx SDU (%d B, tx_sdu_queue_len=%d)\n", - RB_NAME, - ret.error()->N_bytes, - tx_sdu_queue.size()); + logger.warning(ret.error()->msg, + ret.error()->N_bytes, + "[Dropped SDU] %s Tx SDU (%d B, tx_sdu_queue_len=%d)", + RB_NAME, + ret.error()->N_bytes, + tx_sdu_queue.size()); pthread_mutex_unlock(&mutex); return SRSLTE_ERROR; } @@ -386,17 +385,17 @@ int rlc_am_lte::rlc_am_lte_tx::write_sdu(unique_byte_buffer_t sdu) // Store SDU info uint32_t info_count = undelivered_sdu_info_queue.count(info.sn); if (info_count != 0) { - log->error("PDCP SDU info already exists. SN=%d\n", info.sn); + logger.error("PDCP SDU info already exists. SN=%d", info.sn); pthread_mutex_unlock(&mutex); return SRSLTE_ERROR; } if (undelivered_sdu_info_queue.size() >= pdcp_info_queue_capacity) { - log->warning("Undelivered PDCP SDU info queue is growing large. Queue size: %ld\n", - undelivered_sdu_info_queue.size()); + logger.warning("Undelivered PDCP SDU info queue is growing large. Queue size: %ld", + undelivered_sdu_info_queue.size()); } - log->debug("Adding SDU info for PDCP_SN=%d", info.sn); + logger.debug("Adding SDU info for PDCP_SN=%d", info.sn); undelivered_sdu_info_queue[info.sn] = info; pthread_mutex_unlock(&mutex); return SRSLTE_SUCCESS; @@ -407,7 +406,7 @@ void rlc_am_lte::rlc_am_lte_tx::discard_sdu(uint32_t discard_sn) if (!tx_enabled) { return; } - log->warning("Discard SDU not implemented yet\n"); + logger.warning("Discard SDU not implemented yet"); } bool rlc_am_lte::rlc_am_lte_tx::sdu_queue_is_full() @@ -425,11 +424,11 @@ int rlc_am_lte::rlc_am_lte_tx::read_pdu(uint8_t* payload, uint32_t nof_bytes) goto unlock_and_exit; } - log->debug("MAC opportunity - %d bytes\n", nof_bytes); - log->debug("tx_window size - %zu PDUs\n", tx_window.size()); + logger.debug("MAC opportunity - %d bytes", nof_bytes); + logger.debug("tx_window size - %zu PDUs", tx_window.size()); if (not tx_enabled) { - log->debug("RLC entity not active. Not generating PDU.\n"); + logger.debug("RLC entity not active. Not generating PDU."); goto unlock_and_exit; } @@ -464,7 +463,7 @@ void rlc_am_lte::rlc_am_lte_tx::timer_expired(uint32_t timeout_id) { pthread_mutex_lock(&mutex); if (poll_retx_timer.is_valid() && poll_retx_timer.id() == timeout_id) { - log->debug("%s Poll reTx timer expired after %dms\n", RB_NAME, poll_retx_timer.duration()); + logger.debug("%s Poll reTx timer expired after %dms", RB_NAME, poll_retx_timer.duration()); // Section 5.2.2.3 in TS 36.311, schedule PDU for retransmission if // (a) both tx and retx buffer are empty, or // (b) no new data PDU can be transmitted (tx window is full) @@ -484,7 +483,7 @@ void rlc_am_lte::rlc_am_lte_tx::retransmit_pdu() if (not tx_window.empty()) { // select PDU in tx window for retransmission std::map::iterator it = tx_window.begin(); - log->info("%s Schedule SN=%d for reTx.\n", RB_NAME, it->first); + logger.info("%s Schedule SN=%d for reTx.", RB_NAME, it->first); rlc_amd_retx_t retx = {}; retx.is_segment = false; retx.so_start = 0; @@ -544,9 +543,9 @@ bool rlc_am_lte::rlc_am_lte_tx::poll_required() int rlc_am_lte::rlc_am_lte_tx::build_status_pdu(uint8_t* payload, uint32_t nof_bytes) { int pdu_len = parent->rx.get_status_pdu(&tx_status, nof_bytes); - log->debug("%s\n", rlc_am_status_pdu_to_string(&tx_status).c_str()); + logger.debug("%s", rlc_am_status_pdu_to_string(&tx_status).c_str()); if (pdu_len > 0 && nof_bytes >= static_cast(pdu_len)) { - log->info("%s Tx status PDU - %s\n", RB_NAME, rlc_am_status_pdu_to_string(&tx_status).c_str()); + logger.info("%s Tx status PDU - %s", RB_NAME, rlc_am_status_pdu_to_string(&tx_status).c_str()); parent->rx.reset_status(); @@ -557,7 +556,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_status_pdu(uint8_t* payload, uint32_t nof_b debug_state(); pdu_len = rlc_am_write_status_pdu(&tx_status, payload); } else { - log->info("%s Cannot tx status PDU - %d bytes available, %d bytes required\n", RB_NAME, nof_bytes, pdu_len); + logger.info("%s Cannot tx status PDU - %d bytes available, %d bytes required", RB_NAME, nof_bytes, pdu_len); pdu_len = 0; } @@ -568,7 +567,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt { // Check there is at least 1 element before calling front() if (retx_queue.empty()) { - log->error("In build_retx_pdu(): retx_queue is empty\n"); + logger.error("In build_retx_pdu(): retx_queue is empty"); return -1; } @@ -580,7 +579,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt if (!retx_queue.empty()) { retx = retx_queue.front(); } else { - log->info("In build_retx_pdu(): retx_queue is empty during sanity check, sn=%d\n", retx.sn); + logger.info("In build_retx_pdu(): retx_queue is empty during sanity check, sn=%d", retx.sn); return 0; } } @@ -588,13 +587,13 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt // Is resegmentation needed? int req_size = required_buffer_size(retx); if (req_size < 0) { - log->error("In build_retx_pdu(): Removing retx.sn=%d from queue\n", retx.sn); + logger.error("In build_retx_pdu(): Removing retx.sn=%d from queue", retx.sn); retx_queue.pop_front(); return -1; } if (retx.is_segment || req_size > static_cast(nof_bytes)) { - log->debug("%s build_retx_pdu - resegmentation required\n", RB_NAME); + logger.debug("%s build_retx_pdu - resegmentation required", RB_NAME); return build_segment(payload, nof_bytes, retx); } @@ -605,8 +604,8 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt // Set poll bit pdu_without_poll++; byte_without_poll += (tx_window[retx.sn].buf->N_bytes + rlc_am_packed_length(&new_header)); - log->info("%s pdu_without_poll: %d\n", RB_NAME, pdu_without_poll); - log->info("%s byte_without_poll: %d\n", RB_NAME, byte_without_poll); + logger.info("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll); + logger.info("%s byte_without_poll: %d", RB_NAME, byte_without_poll); if (poll_required()) { new_header.p = 1; // vt_s won't change for reTx, so don't update poll_sn @@ -625,19 +624,19 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt retx_queue.pop_front(); tx_window[retx.sn].retx_count++; if (tx_window[retx.sn].retx_count >= cfg.max_retx_thresh) { - log->warning("%s Signaling max number of reTx=%d for for SN=%d\n", RB_NAME, tx_window[retx.sn].retx_count, retx.sn); + logger.warning("%s Signaling max number of reTx=%d for for SN=%d", RB_NAME, tx_window[retx.sn].retx_count, retx.sn); parent->rrc->max_retx_attempted(); } - log->info_hex(payload, - tx_window[retx.sn].buf->N_bytes, - "%s Tx PDU SN=%d (%d B) (attempt %d/%d)\n", - RB_NAME, - retx.sn, - tx_window[retx.sn].buf->N_bytes, - tx_window[retx.sn].retx_count + 1, - cfg.max_retx_thresh); - log->debug("%s\n", rlc_amd_pdu_header_to_string(new_header).c_str()); + logger.info(payload, + tx_window[retx.sn].buf->N_bytes, + "%s Tx PDU SN=%d (%d B) (attempt %d/%d)", + RB_NAME, + retx.sn, + tx_window[retx.sn].buf->N_bytes, + tx_window[retx.sn].retx_count + 1, + cfg.max_retx_thresh); + logger.debug("%s", rlc_amd_pdu_header_to_string(new_header).c_str()); debug_state(); return (ptr - payload) + tx_window[retx.sn].buf->N_bytes; @@ -646,7 +645,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_bytes, rlc_amd_retx_t retx) { if (tx_window[retx.sn].buf == NULL) { - log->error("In build_segment: retx.sn=%d has null buffer\n", retx.sn); + logger.error("In build_segment: retx.sn=%d has null buffer", retx.sn); return 0; } if (!retx.is_segment) { @@ -660,8 +659,8 @@ int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_byte pdu_without_poll++; byte_without_poll += (tx_window[retx.sn].buf->N_bytes + rlc_am_packed_length(&new_header)); - log->info("%s pdu_without_poll: %d\n", RB_NAME, pdu_without_poll); - log->info("%s byte_without_poll: %d\n", RB_NAME, byte_without_poll); + logger.info("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll); + logger.info("%s byte_without_poll: %d", RB_NAME, byte_without_poll); new_header.dc = RLC_DC_FIELD_DATA_PDU; new_header.rf = 1; @@ -672,7 +671,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_byte new_header.N_li = 0; new_header.p = 0; if (poll_required()) { - log->debug("%s setting poll bit to request status\n", RB_NAME); + logger.debug("%s setting poll bit to request status", RB_NAME); new_header.p = 1; // vt_s won't change for reTx, so don't update poll_sn pdu_without_poll = 0; @@ -692,10 +691,10 @@ int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_byte } if (nof_bytes <= head_len) { - log->info("%s Cannot build a PDU segment - %d bytes available, %d bytes required for header\n", - RB_NAME, - nof_bytes, - head_len); + logger.info("%s Cannot build a PDU segment - %d bytes available, %d bytes required for header", + RB_NAME, + nof_bytes, + head_len); return 0; } @@ -788,24 +787,24 @@ int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_byte debug_state(); int pdu_len = (ptr - payload) + len; if (pdu_len > static_cast(nof_bytes)) { - log->error("%s Retx PDU segment length error. Available: %d, Used: %d\n", RB_NAME, nof_bytes, pdu_len); + logger.error("%s Retx PDU segment length error. Available: %d, Used: %d", RB_NAME, nof_bytes, pdu_len); int header_len = (ptr - payload); - log->debug("%s Retx PDU segment length error. Header len: %d, Payload len: %d, N_li: %d\n", - RB_NAME, - header_len, - len, - new_header.N_li); + logger.debug("%s Retx PDU segment length error. Header len: %d, Payload len: %d, N_li: %d", + RB_NAME, + header_len, + len, + new_header.N_li); } - log->info_hex(payload, - pdu_len, - "%s Retx PDU segment SN=%d [so=%d] (%d B) (attempt %d/%d)\n", - RB_NAME, - retx.sn, - retx.so_start, - pdu_len, - tx_window[retx.sn].retx_count + 1, - cfg.max_retx_thresh); + logger.info(payload, + pdu_len, + "%s Retx PDU segment SN=%d [so=%d] (%d B) (attempt %d/%d)", + RB_NAME, + retx.sn, + retx.so_start, + pdu_len, + tx_window[retx.sn].retx_count + 1, + cfg.max_retx_thresh); return pdu_len; } @@ -813,13 +812,13 @@ int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_byte int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) { if (tx_sdu == NULL && tx_sdu_queue.is_empty()) { - log->info("No data available to be sent\n"); + logger.info("No data available to be sent"); return 0; } // do not build any more PDU if window is already full if (tx_sdu == NULL && tx_window.size() >= RLC_AM_WINDOW_SIZE) { - log->info("Tx window full.\n"); + logger.info("Tx window full."); return 0; } @@ -836,7 +835,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt } exit(-1); #else - log->error("Fatal Error: Couldn't allocate PDU in build_data_pdu().\n"); + logger.error("Fatal Error: Couldn't allocate PDU in build_data_pdu()."); return 0; #endif } @@ -852,12 +851,12 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt uint8_t* pdu_ptr = pdu->msg; if (pdu_space <= head_len) { - log->info( - "%s Cannot build a PDU - %d bytes available, %d bytes required for header\n", RB_NAME, nof_bytes, head_len); + logger.info( + "%s Cannot build a PDU - %d bytes available, %d bytes required for header", RB_NAME, nof_bytes, head_len); return 0; } - log->debug("%s Building PDU - pdu_space: %d, head_len: %d \n", RB_NAME, pdu_space, head_len); + logger.debug("%s Building PDU - pdu_space: %d, head_len: %d ", RB_NAME, pdu_space, head_len); // Check for SDU segment if (tx_sdu != NULL) { @@ -870,12 +869,12 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt tx_sdu->msg += to_move; auto info_it = undelivered_sdu_info_queue.find(tx_sdu->md.pdcp_sn); if (info_it == undelivered_sdu_info_queue.end()) { - log->error("Could not find PDCP SN in SDU info queue (segment). PDCP_SN=%d\n", tx_sdu->md.pdcp_sn); + logger.error("Could not find PDCP SN in SDU info queue (segment). PDCP_SN=%d", tx_sdu->md.pdcp_sn); return 0; } undelivered_sdu_info_queue.at(tx_sdu->md.pdcp_sn).rlc_sn_info_list.push_back({header.sn, false}); if (tx_sdu->N_bytes == 0) { - log->debug("%s Complete SDU scheduled for tx.\n", RB_NAME); + logger.debug("%s Complete SDU scheduled for tx.", RB_NAME); undelivered_sdu_info_queue[tx_sdu->md.pdcp_sn].fully_txed = true; tx_sdu.reset(); } @@ -886,11 +885,11 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt } header.fi |= RLC_FI_FIELD_NOT_START_ALIGNED; // First byte does not correspond to first byte of SDU - log->debug("%s Building PDU - added SDU segment (len:%d) - pdu_space: %d, head_len: %d \n", - RB_NAME, - to_move, - pdu_space, - head_len); + logger.debug("%s Building PDU - added SDU segment (len:%d) - pdu_space: %d, head_len: %d ", + RB_NAME, + to_move, + pdu_space, + head_len); } // Pull SDUs from queue @@ -916,12 +915,12 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt tx_sdu->msg += to_move; auto info_it = undelivered_sdu_info_queue.find(tx_sdu->md.pdcp_sn); if (info_it == undelivered_sdu_info_queue.end()) { - log->error("Could not find PDCP SN in SDU info queue. PDCP_SN=%d\n", tx_sdu->md.pdcp_sn); + logger.error("Could not find PDCP SN in SDU info queue. PDCP_SN=%d", tx_sdu->md.pdcp_sn); return 0; } info_it->second.rlc_sn_info_list.push_back({header.sn, false}); if (tx_sdu->N_bytes == 0) { - log->debug("%s Complete SDU scheduled for tx. PDCP SN=%d\n", RB_NAME, tx_sdu->md.pdcp_sn); + logger.debug("%s Complete SDU scheduled for tx. PDCP SN=%d", RB_NAME, tx_sdu->md.pdcp_sn); undelivered_sdu_info_queue[tx_sdu->md.pdcp_sn].fully_txed = true; tx_sdu.reset(); } @@ -931,16 +930,16 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt pdu_space = 0; } - log->debug("%s Building PDU - added SDU segment (len:%d) - pdu_space: %d, head_len: %d \n", - RB_NAME, - to_move, - pdu_space, - head_len); + logger.debug("%s Building PDU - added SDU segment (len:%d) - pdu_space: %d, head_len: %d ", + RB_NAME, + to_move, + pdu_space, + head_len); } // Make sure, at least one SDU (segment) has been added until this point if (pdu->N_bytes == 0) { - log->error("Generated empty RLC PDU.\n"); + logger.error("Generated empty RLC PDU."); return 0; } @@ -951,10 +950,10 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt // Set Poll bit pdu_without_poll++; byte_without_poll += (pdu->N_bytes + head_len); - log->debug("%s pdu_without_poll: %d\n", RB_NAME, pdu_without_poll); - log->debug("%s byte_without_poll: %d\n", RB_NAME, byte_without_poll); + logger.debug("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll); + logger.debug("%s byte_without_poll: %d", RB_NAME, byte_without_poll); if (poll_required()) { - log->debug("%s setting poll bit to request status\n", RB_NAME); + logger.debug("%s setting poll bit to request status", RB_NAME); header.p = 1; poll_sn = vt_s; pdu_without_poll = 0; @@ -979,8 +978,8 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt rlc_am_write_data_pdu_header(&header, &ptr); memcpy(ptr, buffer_ptr->msg, buffer_ptr->N_bytes); int total_len = (ptr - payload) + buffer_ptr->N_bytes; - log->info_hex(payload, total_len, "%s Tx PDU SN=%d (%d B)\n", RB_NAME, header.sn, total_len); - log->debug("%s\n", rlc_amd_pdu_header_to_string(header).c_str()); + logger.info(payload, total_len, "%s Tx PDU SN=%d (%d B)", RB_NAME, header.sn, total_len); + logger.debug("%s", rlc_amd_pdu_header_to_string(header).c_str()); debug_state(); return total_len; @@ -994,17 +993,17 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no pthread_mutex_lock(&mutex); - log->info_hex(payload, nof_bytes, "%s Rx control PDU", RB_NAME); + logger.info(payload, nof_bytes, "%s Rx control PDU", RB_NAME); rlc_status_pdu_t status; rlc_am_read_status_pdu(payload, nof_bytes, &status); - log->info("%s Rx Status PDU: %s\n", RB_NAME, rlc_am_status_pdu_to_string(&status).c_str()); + logger.info("%s Rx Status PDU: %s", RB_NAME, rlc_am_status_pdu_to_string(&status).c_str()); // Sec 5.2.2.2, stop poll reTx timer if status PDU comprises a positive _or_ negative acknowledgement // for the RLC data PDU with sequence number poll_sn if (poll_retx_timer.is_valid() && (TX_MOD_BASE(poll_sn) < TX_MOD_BASE(status.ack_sn))) { - log->debug("%s Stopping pollRetx timer\n", RB_NAME); + logger.debug("%s Stopping pollRetx timer", RB_NAME); poll_retx_timer.stop(); } @@ -1038,9 +1037,9 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no // sanity check if (status.nacks[j].so_start >= it->second.buf->N_bytes) { // print error but try to send original PDU again - log->info("SO_start is larger than original PDU (%d >= %d)\n", - status.nacks[j].so_start, - it->second.buf->N_bytes); + logger.info("SO_start is larger than original PDU (%d >= %d)", + status.nacks[j].so_start, + it->second.buf->N_bytes); status.nacks[j].so_start = 0; } @@ -1056,12 +1055,12 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no retx.is_segment = true; retx.so_start = status.nacks[j].so_start; } else { - log->warning("%s invalid segment NACK received for SN %d. so_start: %d, so_end: %d, N_bytes: %d\n", - RB_NAME, - i, - status.nacks[j].so_start, - status.nacks[j].so_end, - it->second.buf->N_bytes); + logger.warning("%s invalid segment NACK received for SN %d. so_start: %d, so_end: %d, N_bytes: %d", + RB_NAME, + i, + status.nacks[j].so_start, + status.nacks[j].so_end, + it->second.buf->N_bytes); } } retx_queue.push_back(retx); @@ -1092,10 +1091,10 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no // Remove all SDUs that were fully acked for (uint32_t acked_pdcp_sn : notify_info_vec) { - log->debug("Erasing SDU info: PDCP_SN=%d\n", acked_pdcp_sn); + logger.debug("Erasing SDU info: PDCP_SN=%d", acked_pdcp_sn); size_t erased = undelivered_sdu_info_queue.erase(acked_pdcp_sn); if (erased == 0) { - log->error("Could not find info to erase: SN=%d\n", acked_pdcp_sn); + logger.error("Could not find info to erase: SN=%d", acked_pdcp_sn); } } } @@ -1113,10 +1112,10 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no void rlc_am_lte::rlc_am_lte_tx::update_notification_ack_info(const rlc_amd_tx_pdu_t& tx_pdu, std::vector& notify_info_vec) { - log->debug("Updating ACK info: RLC SN=%d, number of notified SDU=%ld, number of undelivered SDUs=%ld", - tx_pdu.header.sn, - notify_info_vec.size(), - undelivered_sdu_info_queue.size()); + logger.debug("Updating ACK info: RLC SN=%d, number of notified SDU=%ld, number of undelivered SDUs=%ld", + tx_pdu.header.sn, + notify_info_vec.size(), + undelivered_sdu_info_queue.size()); // Iterate over all undelivered SDUs for (auto& info_it : undelivered_sdu_info_queue) { // Iterate over all SNs that were TX'ed @@ -1143,7 +1142,7 @@ void rlc_am_lte::rlc_am_lte_tx::update_notification_ack_info(const rlc_amd_tx_pd void rlc_am_lte::rlc_am_lte_tx::debug_state() { - log->debug("%s vt_a = %d, vt_ms = %d, vt_s = %d, poll_sn = %d\n", RB_NAME, vt_a, vt_ms, vt_s, poll_sn); + logger.debug("%s vt_a = %d, vt_ms = %d, vt_s = %d, poll_sn = %d", RB_NAME, vt_a, vt_ms, vt_s, poll_sn); } int rlc_am_lte::rlc_am_lte_tx::required_buffer_size(rlc_amd_retx_t retx) @@ -1153,11 +1152,11 @@ int rlc_am_lte::rlc_am_lte_tx::required_buffer_size(rlc_amd_retx_t retx) if (tx_window[retx.sn].buf) { return rlc_am_packed_length(&tx_window[retx.sn].header) + tx_window[retx.sn].buf->N_bytes; } else { - log->warning("retx.sn=%d has null ptr in required_buffer_size()\n", retx.sn); + logger.warning("retx.sn=%d has null ptr in required_buffer_size()", retx.sn); return -1; } } else { - log->warning("retx.sn=%d does not exist in required_buffer_size()\n", retx.sn); + logger.warning("retx.sn=%d does not exist in required_buffer_size()", retx.sn); return -1; } } @@ -1237,7 +1236,7 @@ bool rlc_am_lte::rlc_am_lte_tx::retx_queue_has_sn(uint32_t sn) rlc_am_lte::rlc_am_lte_rx::rlc_am_lte_rx(rlc_am_lte* parent_) : parent(parent_), pool(byte_buffer_pool::get_instance()), - log(parent_->log), + logger(parent_->logger), reordering_timer(parent_->timers->get_unique_timer()) { pthread_mutex_init(&mutex, NULL); @@ -1255,7 +1254,7 @@ bool rlc_am_lte::rlc_am_lte_rx::configure(rlc_am_config_t cfg_) // check timers if (not reordering_timer.is_valid()) { - log->error("Configuring RLC AM TX: timers not configured\n"); + logger.error("Configuring RLC AM TX: timers not configured"); return false; } @@ -1310,8 +1309,8 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b { std::map::iterator it; - log->info_hex(payload, nof_bytes, "%s Rx data PDU SN=%d (%d B)", RB_NAME, header.sn, nof_bytes); - log->debug("%s\n", rlc_amd_pdu_header_to_string(header).c_str()); + logger.info(payload, nof_bytes, "%s Rx data PDU SN=%d (%d B)", RB_NAME, header.sn, nof_bytes); + logger.debug("%s", rlc_amd_pdu_header_to_string(header).c_str()); // sanity check for segments not exceeding PDU length if (header.N_li > 0) { @@ -1319,7 +1318,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b for (uint32_t i = 0; i < header.N_li; i++) { segments_len += header.li[i]; if (segments_len > nof_bytes) { - log->info("Dropping corrupted PDU (segments_len=%d > pdu_len=%d)\n", segments_len, nof_bytes); + logger.info("Dropping corrupted PDU (segments_len=%d > pdu_len=%d)", segments_len, nof_bytes); return; } } @@ -1327,20 +1326,20 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b if (!inside_rx_window(header.sn)) { if (header.p) { - log->info("%s Status packet requested through polling bit\n", RB_NAME); + logger.info("%s Status packet requested through polling bit", RB_NAME); do_status = true; } - log->info("%s SN=%d outside rx window [%d:%d] - discarding\n", RB_NAME, header.sn, vr_r, vr_mr); + logger.info("%s SN=%d outside rx window [%d:%d] - discarding", RB_NAME, header.sn, vr_r, vr_mr); return; } it = rx_window.find(header.sn); if (rx_window.end() != it) { if (header.p) { - log->info("%s Status packet requested through polling bit\n", RB_NAME); + logger.info("%s Status packet requested through polling bit", RB_NAME); do_status = true; } - log->info("%s Discarding duplicate SN=%d\n", RB_NAME, header.sn); + logger.info("%s Discarding duplicate SN=%d", RB_NAME, header.sn); return; } @@ -1352,7 +1351,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b srslte::console("Fatal Error: Couldn't allocate PDU in handle_data_pdu().\n"); exit(-1); #else - log->error("Fatal Error: Couldn't allocate PDU in handle_data_pdu().\n"); + logger.error("Fatal Error: Couldn't allocate PDU in handle_data_pdu()."); return; #endif } @@ -1360,11 +1359,11 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b // check available space for payload if (nof_bytes > pdu.buf->get_tailroom()) { - log->error("%s Discarding SN=%d of size %d B (available space %d B)\n", - RB_NAME, - header.sn, - nof_bytes, - pdu.buf->get_tailroom()); + logger.error("%s Discarding SN=%d of size %d B (available space %d B)", + RB_NAME, + header.sn, + nof_bytes, + pdu.buf->get_tailroom()); return; } memcpy(pdu.buf->msg, payload, nof_bytes); @@ -1387,7 +1386,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b // Check poll bit if (header.p) { - log->info("%s Status packet requested through polling bit\n", RB_NAME); + logger.info("%s Status packet requested through polling bit", RB_NAME); poll_received = true; // 36.322 v10 Section 5.2.3 @@ -1404,21 +1403,21 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b if (reordering_timer.is_valid()) { if (reordering_timer.is_running()) { if (vr_x == vr_r || (!inside_rx_window(vr_x) && vr_x != vr_mr)) { - log->debug("Stopping reordering timer.\n"); + logger.debug("Stopping reordering timer."); reordering_timer.stop(); } else { - log->debug("Leave reordering timer running.\n"); + logger.debug("Leave reordering timer running."); } debug_state(); } if (not reordering_timer.is_running()) { if (RX_MOD_BASE(vr_h) > RX_MOD_BASE(vr_r)) { - log->debug("Starting reordering timer.\n"); + logger.debug("Starting reordering timer."); reordering_timer.run(); vr_x = vr_h; } else { - log->debug("Leave reordering timer stopped.\n"); + logger.debug("Leave reordering timer stopped."); } debug_state(); } @@ -1433,23 +1432,23 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* pa { std::map::iterator it; - log->info_hex(payload, - nof_bytes, - "%s Rx data PDU segment of SN=%d (%d B), SO=%d, N_li=%d", - RB_NAME, - header.sn, - nof_bytes, - header.so, - header.N_li); - log->debug("%s\n", rlc_amd_pdu_header_to_string(header).c_str()); + logger.info(payload, + nof_bytes, + "%s Rx data PDU segment of SN=%d (%d B), SO=%d, N_li=%d", + RB_NAME, + header.sn, + nof_bytes, + header.so, + header.N_li); + logger.debug("%s", rlc_amd_pdu_header_to_string(header).c_str()); // Check inside rx window if (!inside_rx_window(header.sn)) { if (header.p) { - log->info("%s Status packet requested through polling bit\n", RB_NAME); + logger.info("%s Status packet requested through polling bit", RB_NAME); do_status = true; } - log->info("%s SN=%d outside rx window [%d:%d] - discarding\n", RB_NAME, header.sn, vr_r, vr_mr); + logger.info("%s SN=%d outside rx window [%d:%d] - discarding", RB_NAME, header.sn, vr_r, vr_mr); return; } @@ -1460,13 +1459,13 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* pa srslte::console("Fatal Error: Couldn't allocate PDU in handle_data_pdu_segment().\n"); exit(-1); #else - log->error("Fatal Error: Couldn't allocate PDU in handle_data_pdu_segment().\n"); + logger.error("Fatal Error: Couldn't allocate PDU in handle_data_pdu_segment()."); return; #endif } if (segment.buf->get_tailroom() < nof_bytes) { - log->info("Dropping corrupted segment SN=%d, not enough space to fit %d B\n", header.sn, nof_bytes); + logger.info("Dropping corrupted segment SN=%d, not enough space to fit %d B", header.sn, nof_bytes); return; } @@ -1478,7 +1477,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* pa it = rx_segments.find(header.sn); if (rx_segments.end() != it) { if (header.p) { - log->info("%s Status packet requested through polling bit\n", RB_NAME); + logger.info("%s Status packet requested through polling bit", RB_NAME); do_status = true; } @@ -1501,7 +1500,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* pa // Check poll bit if (header.p) { - log->info("%s Status packet requested through polling bit\n", RB_NAME); + logger.info("%s Status packet requested through polling bit", RB_NAME); poll_received = true; // 36.322 v10 Section 5.2.3 @@ -1527,7 +1526,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() srslte::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (1)\n"); exit(-1); #else - log->error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (1)\n"); + logger.error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (1)"); return; #endif } @@ -1539,13 +1538,13 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() for (uint32_t i = 0; i < rx_window[vr_r].header.N_li; i++) { len = rx_window[vr_r].header.li[i]; - log->debug_hex(rx_window[vr_r].buf->msg, - len, - "Handling segment %d/%d of length %d B of SN=%d\n", - i + 1, - rx_window[vr_r].header.N_li, - len, - vr_r); + logger.debug(rx_window[vr_r].buf->msg, + len, + "Handling segment %d/%d of length %d B of SN=%d", + i + 1, + rx_window[vr_r].header.N_li, + len, + vr_r); // sanity check to avoid zero-size SDUs if (len == 0) { @@ -1555,7 +1554,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() if (rx_sdu->get_tailroom() >= len) { if ((rx_window[vr_r].buf->msg - rx_window[vr_r].buf->buffer) + len < SRSLTE_MAX_BUFFER_SIZE_BYTES) { if (rx_window[vr_r].buf->N_bytes < len) { - log->error("Dropping corrupted SN=%d\n", vr_r); + logger.error("Dropping corrupted SN=%d", vr_r); rx_sdu.reset(); goto exit; } @@ -1569,7 +1568,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() rx_window[vr_r].buf->msg += len; rx_window[vr_r].buf->N_bytes -= len; - log->info_hex(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes); + logger.info(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes); sdu_rx_latency_ms.push(std::chrono::duration_cast( std::chrono::high_resolution_clock::now() - rx_sdu->get_timestamp()) .count()); @@ -1582,18 +1581,18 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() srslte::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (2)\n"); exit(-1); #else - log->error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (2)\n"); + logger.error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (2)"); return; #endif } } else { int buf_len = rx_window[vr_r].buf->msg - rx_window[vr_r].buf->buffer; - log->error("Cannot read %d bytes from rx_window. vr_r=%d, msg-buffer=%d B\n", len, vr_r, buf_len); + logger.error("Cannot read %d bytes from rx_window. vr_r=%d, msg-buffer=%d B", len, vr_r, buf_len); rx_sdu.reset(); goto exit; } } else { - log->error("Cannot fit RLC PDU in SDU buffer, dropping both.\n"); + logger.error("Cannot fit RLC PDU in SDU buffer, dropping both."); rx_sdu.reset(); goto exit; } @@ -1601,7 +1600,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() // Handle last segment len = rx_window[vr_r].buf->N_bytes; - log->debug_hex(rx_window[vr_r].buf->msg, len, "Handling last segment of length %d B of SN=%d\n", len, vr_r); + logger.debug(rx_window[vr_r].buf->msg, len, "Handling last segment of length %d B of SN=%d", len, vr_r); if (rx_sdu->get_tailroom() >= len) { // store timestamp of the first segment when starting to assemble SDUs if (rx_sdu->N_bytes == 0) { @@ -1619,7 +1618,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() } if (rlc_am_end_aligned(rx_window[vr_r].header.fi)) { - log->info_hex(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes); + logger.info(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes); sdu_rx_latency_ms.push(std::chrono::duration_cast( std::chrono::high_resolution_clock::now() - rx_sdu->get_timestamp()) .count()); @@ -1632,7 +1631,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() srslte::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (3)\n"); exit(-1); #else - log->error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (3)\n"); + logger.error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (3)"); return; #endif } @@ -1640,19 +1639,19 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus() exit: // Move the rx_window - log->debug("Erasing SN=%d.\n", vr_r); + logger.debug("Erasing SN=%d.", vr_r); // also erase any segments of this SN std::map::iterator it; it = rx_segments.find(vr_r); if (rx_segments.end() != it) { - log->debug("Erasing segments of SN=%d\n", vr_r); + logger.debug("Erasing segments of SN=%d", vr_r); std::list::iterator segit; for (segit = it->second.segments.begin(); segit != it->second.segments.end(); ++segit) { - log->debug(" Erasing segment of SN=%d SO=%d Len=%d N_li=%d\n", - segit->header.sn, - segit->header.so, - segit->buf->N_bytes, - segit->header.N_li); + logger.debug(" Erasing segment of SN=%d SO=%d Len=%d N_li=%d", + segit->header.sn, + segit->header.so, + segit->buf->N_bytes, + segit->header.N_li); } it->second.segments.clear(); } @@ -1691,7 +1690,7 @@ void rlc_am_lte::rlc_am_lte_rx::write_pdu(uint8_t* payload, const uint32_t nof_b uint32_t payload_len = nof_bytes; rlc_am_read_data_pdu_header(&payload, &payload_len, &header); if (payload_len > nof_bytes) { - log->info("Dropping corrupted PDU (%d B). Remaining length after header %d B.\n", nof_bytes, payload_len); + logger.info("Dropping corrupted PDU (%d B). Remaining length after header %d B.", nof_bytes, payload_len); pthread_mutex_unlock(&mutex); return; } @@ -1733,7 +1732,7 @@ void rlc_am_lte::rlc_am_lte_rx::timer_expired(uint32_t timeout_id) { pthread_mutex_lock(&mutex); if (reordering_timer.is_valid() and reordering_timer.id() == timeout_id) { - log->debug("%s reordering timeout expiry - updating vr_ms (was %d)\n", RB_NAME, vr_ms); + logger.debug("%s reordering timeout expiry - updating vr_ms (was %d)", RB_NAME, vr_ms); // 36.322 v10 Section 5.1.3.2.4 vr_ms = vr_x; @@ -1777,21 +1776,21 @@ int rlc_am_lte::rlc_am_lte_rx::get_status_pdu(rlc_status_pdu_t* status, const ui // make sure we don't exceed grant size if (rlc_am_packed_length(status) > max_pdu_size) { - log->debug("Status PDU too big (%d > %d)\n", rlc_am_packed_length(status), max_pdu_size); + logger.debug("Status PDU too big (%d > %d)", rlc_am_packed_length(status), max_pdu_size); if (status->N_nack >= 1 && status->N_nack < RLC_AM_WINDOW_SIZE) { - log->debug("Removing last NACK SN=%d\n", status->nacks[status->N_nack].nack_sn); + logger.debug("Removing last NACK SN=%d", status->nacks[status->N_nack].nack_sn); status->N_nack--; // make sure we don't have the current ACK_SN in the NACK list if (rlc_am_is_valid_status_pdu(*status) == false) { // No space to send any NACKs - log->debug("Resetting N_nack to zero\n"); + logger.debug("Resetting N_nack to zero"); status->N_nack = 0; } } else { - log->warning("Failed to generate small enough status PDU (packed_len=%d, max_pdu_size=%d, status->N_nack=%d)\n", - rlc_am_packed_length(status), - max_pdu_size, - status->N_nack); + logger.warning("Failed to generate small enough status PDU (packed_len=%d, max_pdu_size=%d, status->N_nack=%d)", + rlc_am_packed_length(status), + max_pdu_size, + status->N_nack); } break; } @@ -1831,7 +1830,7 @@ void rlc_am_lte::rlc_am_lte_rx::print_rx_segments() << " N_li: " << segit->header.N_li << std::endl; } } - log->debug("%s\n", ss.str().c_str()); + logger.debug("%s", ss.str().c_str()); } // NOTE: Preference would be to capture by value, and then move; but header is stack allocated @@ -1905,25 +1904,25 @@ bool rlc_am_lte::rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* header.fi |= (pdu->segments.front().header.fi & RLC_FI_FIELD_NOT_START_ALIGNED); header.fi |= (pdu->segments.back().header.fi & RLC_FI_FIELD_NOT_END_ALIGNED); - log->debug("Starting header reconstruction of %zd segments\n", pdu->segments.size()); + logger.debug("Starting header reconstruction of %zd segments", pdu->segments.size()); // Reconstruct li fields uint16_t count = 0; uint16_t carryover = 0; for (it = pdu->segments.begin(); it != pdu->segments.end(); it++) { - log->debug(" Handling %d PDU segments\n", it->header.N_li); + logger.debug(" Handling %d PDU segments", it->header.N_li); for (uint32_t i = 0; i < it->header.N_li; i++) { header.li[header.N_li] = it->header.li[i]; if (i == 0) { header.li[header.N_li] += carryover; } - log->debug(" - adding segment %d/%d (%d B, SO=%d, carryover=%d, count=%d)\n", - i + 1, - it->header.N_li, - header.li[header.N_li], - header.so, - carryover, - count); + logger.debug(" - adding segment %d/%d (%d B, SO=%d, carryover=%d, count=%d)", + i + 1, + it->header.N_li, + header.li[header.N_li], + header.so, + carryover, + count); header.N_li++; count += it->header.li[i]; carryover = 0; @@ -1931,24 +1930,24 @@ bool rlc_am_lte::rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* if (count <= it->buf->N_bytes) { carryover += it->buf->N_bytes - count; - log->debug("Incremented carryover (it->buf->N_bytes=%d, count=%d). New carryover=%d\n", - it->buf->N_bytes, - count, - carryover); + logger.debug("Incremented carryover (it->buf->N_bytes=%d, count=%d). New carryover=%d", + it->buf->N_bytes, + count, + carryover); } else { // Next segment would be too long, recalculate carryover header.N_li--; carryover = it->buf->N_bytes - (count - header.li[header.N_li]); - log->debug("Recalculated carryover=%d (it->buf->N_bytes=%d, count=%d, header.li[header.N_li]=%d)\n", - carryover, - it->buf->N_bytes, - count, - header.li[header.N_li]); + logger.debug("Recalculated carryover=%d (it->buf->N_bytes=%d, count=%d, header.li[header.N_li]=%d)", + carryover, + it->buf->N_bytes, + count, + header.li[header.N_li]); } tmpit = it; if (rlc_am_end_aligned(it->header.fi) && ++tmpit != pdu->segments.end()) { - log->debug("Header is end-aligned, overwrite header.li[%d]=%d\n", header.N_li, carryover); + logger.debug("Header is end-aligned, overwrite header.li[%d]=%d", header.N_li, carryover); header.li[header.N_li] = carryover; header.N_li++; carryover = 0; @@ -1959,7 +1958,7 @@ bool rlc_am_lte::rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* header.p |= it->header.p; } - log->debug("Finished header reconstruction of %zd segments\n", pdu->segments.size()); + logger.debug("Finished header reconstruction of %zd segments", pdu->segments.size()); // Copy data unique_byte_buffer_t full_pdu = srslte::make_byte_buffer(); @@ -1968,7 +1967,7 @@ bool rlc_am_lte::rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* srslte::console("Fatal Error: Could not allocate PDU in add_segment_and_check()\n"); exit(-1); #else - log->error("Fatal Error: Could not allocate PDU in add_segment_and_check()\n"); + logger.error("Fatal Error: Could not allocate PDU in add_segment_and_check()"); return false; #endif } @@ -2004,7 +2003,7 @@ bool rlc_am_lte::rlc_am_lte_rx::inside_rx_window(const int16_t sn) void rlc_am_lte::rlc_am_lte_rx::debug_state() { - log->debug("%s vr_r = %d, vr_mr = %d, vr_x = %d, vr_ms = %d, vr_h = %d\n", RB_NAME, vr_r, vr_mr, vr_x, vr_ms, vr_h); + logger.debug("%s vr_r = %d, vr_mr = %d, vr_x = %d, vr_ms = %d, vr_h = %d", RB_NAME, vr_r, vr_mr, vr_x, vr_ms, vr_h); } /**************************************************************************** diff --git a/lib/src/upper/rlc_tm.cc b/lib/src/upper/rlc_tm.cc index bc44184fd..e7dddf888 100644 --- a/lib/src/upper/rlc_tm.cc +++ b/lib/src/upper/rlc_tm.cc @@ -14,8 +14,11 @@ namespace srslte { -rlc_tm::rlc_tm(srslte::log_ref log_, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_) : - log(log_), pdcp(pdcp_), rrc(rrc_), lcid(lcid_) +rlc_tm::rlc_tm(srslog::basic_logger& logger, + uint32_t lcid_, + srsue::pdcp_interface_rlc* pdcp_, + srsue::rrc_interface_rlc* rrc_) : + logger(logger), pdcp(pdcp_), rrc(rrc_), lcid(lcid_) { pool = byte_buffer_pool::get_instance(); } @@ -28,7 +31,7 @@ rlc_tm::~rlc_tm() bool rlc_tm::configure(const rlc_config_t& cnfg) { - log->error("Attempted to configure TM RLC entity\n"); + logger.error("Attempted to configure TM RLC entity"); return true; } @@ -74,23 +77,23 @@ void rlc_tm::write_sdu(unique_byte_buffer_t sdu) uint32_t nof_bytes = sdu->N_bytes; srslte::error_type ret = ul_queue.try_write(std::move(sdu)); if (ret) { - log->info_hex(msg_ptr, - nof_bytes, - "%s Tx SDU, queue size=%d, bytes=%d", - rrc->get_rb_name(lcid).c_str(), - ul_queue.size(), - ul_queue.size_bytes()); + logger.info(msg_ptr, + nof_bytes, + "%s Tx SDU, queue size=%d, bytes=%d", + rrc->get_rb_name(lcid).c_str(), + ul_queue.size(), + ul_queue.size_bytes()); } else { - log->warning_hex(ret.error()->msg, - ret.error()->N_bytes, - "[Dropped SDU] %s Tx SDU, queue size=%d, bytes=%d", - rrc->get_rb_name(lcid).c_str(), - ul_queue.size(), - ul_queue.size_bytes()); + logger.warning(ret.error()->msg, + ret.error()->N_bytes, + "[Dropped SDU] %s Tx SDU, queue size=%d, bytes=%d", + rrc->get_rb_name(lcid).c_str(), + ul_queue.size(), + ul_queue.size_bytes()); } } else { - log->warning("NULL SDU pointer in write_sdu()\n"); + logger.warning("NULL SDU pointer in write_sdu()"); } } @@ -99,7 +102,7 @@ void rlc_tm::discard_sdu(uint32_t discard_sn) if (!tx_enabled) { return; } - log->warning("SDU discard not implemented on RLC TM\n"); + logger.warning("SDU discard not implemented on RLC TM"); } bool rlc_tm::sdu_queue_is_full() @@ -132,31 +135,31 @@ int rlc_tm::read_pdu(uint8_t* payload, uint32_t nof_bytes) { uint32_t pdu_size = ul_queue.size_tail_bytes(); if (pdu_size > nof_bytes) { - log->info( - "%s Tx PDU size larger than MAC opportunity (%d > %d)\n", rrc->get_rb_name(lcid).c_str(), pdu_size, nof_bytes); + logger.info( + "%s Tx PDU size larger than MAC opportunity (%d > %d)", rrc->get_rb_name(lcid).c_str(), pdu_size, nof_bytes); return -1; } unique_byte_buffer_t buf; if (ul_queue.try_read(&buf)) { pdu_size = buf->N_bytes; memcpy(payload, buf->msg, buf->N_bytes); - log->debug("%s Complete SDU scheduled for tx. Stack latency: %" PRIu64 " us\n", - rrc->get_rb_name(lcid).c_str(), - (uint64_t)buf->get_latency_us().count()); - log->info_hex(payload, - pdu_size, - "%s Tx %s PDU, queue size=%d, bytes=%d", - rrc->get_rb_name(lcid).c_str(), - srslte::to_string(rlc_mode_t::tm).c_str(), - ul_queue.size(), - ul_queue.size_bytes()); + logger.debug("%s Complete SDU scheduled for tx. Stack latency: %" PRIu64 " us", + rrc->get_rb_name(lcid).c_str(), + (uint64_t)buf->get_latency_us().count()); + logger.info(payload, + pdu_size, + "%s Tx %s PDU, queue size=%d, bytes=%d", + rrc->get_rb_name(lcid).c_str(), + srslte::to_string(rlc_mode_t::tm).c_str(), + ul_queue.size(), + ul_queue.size_bytes()); metrics.num_tx_pdu_bytes += pdu_size; return pdu_size; } else { - log->warning("Queue empty while trying to read\n"); + logger.warning("Queue empty while trying to read"); if (ul_queue.size_bytes() > 0) { - log->warning("Corrupted queue: empty but size_bytes > 0. Resetting queue\n"); + logger.warning("Corrupted queue: empty but size_bytes > 0. Resetting queue"); ul_queue.reset(); } return 0; @@ -178,7 +181,7 @@ void rlc_tm::write_pdu(uint8_t* payload, uint32_t nof_bytes) pdcp->write_pdu(lcid, std::move(buf)); } } else { - log->error("Fatal Error: Couldn't allocate buffer in rlc_tm::write_pdu().\n"); + logger.error("Fatal Error: Couldn't allocate buffer in rlc_tm::write_pdu()."); } } diff --git a/lib/src/upper/rlc_um_base.cc b/lib/src/upper/rlc_um_base.cc index 3108a56f2..5d1809c1b 100644 --- a/lib/src/upper/rlc_um_base.cc +++ b/lib/src/upper/rlc_um_base.cc @@ -15,12 +15,12 @@ namespace srslte { -rlc_um_base::rlc_um_base(srslte::log_ref log_, +rlc_um_base::rlc_um_base(srslog::basic_logger& logger, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_, srslte::timer_handler* timers_) : - log(log_), lcid(lcid_), pdcp(pdcp_), rrc(rrc_), timers(timers_), pool(byte_buffer_pool::get_instance()) + logger(logger), lcid(lcid_), pdcp(pdcp_), rrc(rrc_), timers(timers_), pool(byte_buffer_pool::get_instance()) {} rlc_um_base::~rlc_um_base() {} @@ -80,7 +80,7 @@ void rlc_um_base::empty_queue() void rlc_um_base::write_sdu(unique_byte_buffer_t sdu) { if (not tx_enabled || not tx) { - log->debug("%s is currently deactivated. Dropping SDU (%d B)\n", rb_name.c_str(), sdu->N_bytes); + logger.debug("%s is currently deactivated. Dropping SDU (%d B)", rb_name.c_str(), sdu->N_bytes); metrics.num_lost_sdus++; return; } @@ -97,7 +97,7 @@ void rlc_um_base::write_sdu(unique_byte_buffer_t sdu) void rlc_um_base::discard_sdu(uint32_t discard_sn) { if (not tx_enabled || not tx) { - log->debug("%s is currently deactivated. Ignoring SDU discard (SN=%u)\n", rb_name.c_str(), discard_sn); + logger.debug("%s is currently deactivated. Ignoring SDU discard (SN=%u)", rb_name.c_str(), discard_sn); return; } tx->discard_sdu(discard_sn); @@ -182,7 +182,7 @@ std::string rlc_um_base::get_rb_name(srsue::rrc_interface_rlc* rrc, uint32_t lci rlc_um_base::rlc_um_base_rx::rlc_um_base_rx(rlc_um_base* parent_) : pool(parent_->pool), - log(parent_->log), + logger(parent_->logger), timers(parent_->timers), pdcp(parent_->pdcp), rrc(parent_->rrc), @@ -198,7 +198,7 @@ rlc_um_base::rlc_um_base_rx::~rlc_um_base_rx() {} ***************************************************************************/ rlc_um_base::rlc_um_base_tx::rlc_um_base_tx(rlc_um_base* parent_) : - log(parent_->log), pool(parent_->pool), parent(parent_) + logger(parent_->logger), pool(parent_->pool), parent(parent_) {} rlc_um_base::rlc_um_base_tx::~rlc_um_base_tx() {} @@ -236,15 +236,15 @@ bool rlc_um_base::rlc_um_base_tx::has_data() void rlc_um_base::rlc_um_base_tx::write_sdu(unique_byte_buffer_t sdu) { if (sdu) { - log->info_hex(sdu->msg, - sdu->N_bytes, - "%s Tx SDU (%d B, tx_sdu_queue_len=%d)", - rb_name.c_str(), - sdu->N_bytes, - tx_sdu_queue.size()); + logger.info(sdu->msg, + sdu->N_bytes, + "%s Tx SDU (%d B, tx_sdu_queue_len=%d)", + rb_name.c_str(), + sdu->N_bytes, + tx_sdu_queue.size()); tx_sdu_queue.write(std::move(sdu)); } else { - log->warning("NULL SDU pointer in write_sdu()\n"); + logger.warning("NULL SDU pointer in write_sdu()"); } } @@ -255,26 +255,26 @@ int rlc_um_base::rlc_um_base_tx::try_write_sdu(unique_byte_buffer_t sdu) uint32_t nof_bytes = sdu->N_bytes; srslte::error_type ret = tx_sdu_queue.try_write(std::move(sdu)); if (ret) { - log->info_hex( + logger.info( msg_ptr, nof_bytes, "%s Tx SDU (%d B, tx_sdu_queue_len=%d)", rb_name.c_str(), nof_bytes, tx_sdu_queue.size()); return SRSLTE_SUCCESS; } else { - log->warning_hex(ret.error()->msg, - ret.error()->N_bytes, - "[Dropped SDU] %s Tx SDU (%d B, tx_sdu_queue_len=%d)", - rb_name.c_str(), - ret.error()->N_bytes, - tx_sdu_queue.size()); + logger.warning(ret.error()->msg, + ret.error()->N_bytes, + "[Dropped SDU] %s Tx SDU (%d B, tx_sdu_queue_len=%d)", + rb_name.c_str(), + ret.error()->N_bytes, + tx_sdu_queue.size()); } } else { - log->warning("NULL SDU pointer in write_sdu()\n"); + logger.warning("NULL SDU pointer in write_sdu()"); } return SRSLTE_ERROR; } void rlc_um_base::rlc_um_base_tx::discard_sdu(uint32_t discard_sn) { - log->warning("RLC UM: Discard SDU not implemented yet.\n"); + logger.warning("RLC UM: Discard SDU not implemented yet."); } bool rlc_um_base::rlc_um_base_tx::sdu_queue_is_full() @@ -287,16 +287,16 @@ int rlc_um_base::rlc_um_base_tx::build_data_pdu(uint8_t* payload, uint32_t nof_b unique_byte_buffer_t pdu; { std::lock_guard lock(mutex); - log->debug("MAC opportunity - %d bytes\n", nof_bytes); + logger.debug("MAC opportunity - %d bytes", nof_bytes); if (tx_sdu == nullptr && tx_sdu_queue.is_empty()) { - log->info("No data available to be sent\n"); + logger.info("No data available to be sent"); return 0; } pdu = make_byte_buffer(); if (!pdu || pdu->N_bytes != 0) { - log->error("Failed to allocate PDU buffer\n"); + logger.error("Failed to allocate PDU buffer"); return 0; } } diff --git a/lib/src/upper/rlc_um_lte.cc b/lib/src/upper/rlc_um_lte.cc index 9e3a15e1d..bc48a252d 100644 --- a/lib/src/upper/rlc_um_lte.cc +++ b/lib/src/upper/rlc_um_lte.cc @@ -17,12 +17,12 @@ namespace srslte { -rlc_um_lte::rlc_um_lte(srslte::log_ref log_, +rlc_um_lte::rlc_um_lte(srslog::basic_logger& logger, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_, srslte::timer_handler* timers_) : - rlc_um_base(log_, lcid_, pdcp_, rrc_, timers_) + rlc_um_base(logger, lcid_, pdcp_, rrc_, timers_) {} // Warning: must call stop() to properly deallocate all buffers @@ -49,12 +49,12 @@ bool rlc_um_lte::configure(const rlc_config_t& cnfg_) return false; } - log->info("%s configured in %s: t_reordering=%d ms, rx_sn_field_length=%u bits, tx_sn_field_length=%u bits\n", - rb_name.c_str(), - srslte::to_string(cnfg_.rlc_mode).c_str(), - cfg.um.t_reordering, - srslte::to_number(cfg.um.rx_sn_field_length), - srslte::to_number(cfg.um.tx_sn_field_length)); + logger.info("%s configured in %s: t_reordering=%d ms, rx_sn_field_length=%u bits, tx_sn_field_length=%u bits", + rb_name.c_str(), + srslte::to_string(cnfg_.rlc_mode).c_str(), + cfg.um.t_reordering, + srslte::to_number(cfg.um.rx_sn_field_length), + srslte::to_number(cfg.um.tx_sn_field_length)); rx_enabled = true; tx_enabled = true; @@ -97,7 +97,7 @@ bool rlc_um_lte::rlc_um_lte_tx::configure(const rlc_config_t& cnfg_, std::string cfg = cnfg_; if (cfg.um.tx_mod == 0) { - log->error("Error configuring %s RLC UM: tx_mod==0\n", rb_name.c_str()); + logger.error("Error configuring %s RLC UM: tx_mod==0", rb_name.c_str()); return false; } @@ -125,10 +125,10 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* int pdu_space = SRSLTE_MIN(nof_bytes, pdu->get_tailroom()); if (pdu_space <= head_len + 1) { - log->info("%s Cannot build a PDU - %d bytes available, %d bytes required for header\n", - rb_name.c_str(), - nof_bytes, - head_len); + logger.info("%s Cannot build a PDU - %d bytes available, %d bytes required for header", + rb_name.c_str(), + nof_bytes, + head_len); return 0; } @@ -136,8 +136,8 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* if (tx_sdu) { uint32_t space = pdu_space - head_len; to_move = space >= tx_sdu->N_bytes ? tx_sdu->N_bytes : space; - log->debug( - "%s adding remainder of SDU segment - %d bytes of %d remaining\n", rb_name.c_str(), to_move, tx_sdu->N_bytes); + logger.debug( + "%s adding remainder of SDU segment - %d bytes of %d remaining", rb_name.c_str(), to_move, tx_sdu->N_bytes); memcpy(pdu_ptr, tx_sdu->msg, to_move); last_li = to_move; pdu_ptr += to_move; @@ -148,12 +148,12 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* #ifdef ENABLE_TIMESTAMP auto latency_us = tx_sdu->get_latency_us().count(); mean_pdu_latency_us.push(latency_us); - log->debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us\n", - rb_name.c_str(), - (uint64_t)latency_us, - (long)mean_pdu_latency_us.value()); + logger.debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us", + rb_name.c_str(), + (uint64_t)latency_us, + (long)mean_pdu_latency_us.value()); #else - log->debug("%s Complete SDU scheduled for tx.\n", rb_name.c_str()); + logger.debug("%s Complete SDU scheduled for tx.", rb_name.c_str()); #endif tx_sdu.reset(); } @@ -163,7 +163,7 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* // Pull SDUs from queue while (pdu_space > head_len + 1 && tx_sdu_queue.size() > 0) { - log->debug("pdu_space=%d, head_len=%d\n", pdu_space, head_len); + logger.debug("pdu_space=%d, head_len=%d", pdu_space, head_len); if (last_li > 0) { header.li[header.N_li++] = last_li; } @@ -176,7 +176,7 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* } tx_sdu = tx_sdu_queue.read(); to_move = (space >= tx_sdu->N_bytes) ? tx_sdu->N_bytes : space; - log->debug("%s adding new SDU segment - %d bytes of %d remaining\n", rb_name.c_str(), to_move, tx_sdu->N_bytes); + logger.debug("%s adding new SDU segment - %d bytes of %d remaining", rb_name.c_str(), to_move, tx_sdu->N_bytes); memcpy(pdu_ptr, tx_sdu->msg, to_move); last_li = to_move; pdu_ptr += to_move; @@ -187,12 +187,12 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* #ifdef ENABLE_TIMESTAMP auto latency_us = tx_sdu->get_latency_us().count(); mean_pdu_latency_us.push(latency_us); - log->debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us\n", - rb_name.c_str(), - (uint64_t)latency_us, - (long)mean_pdu_latency_us.value()); + logger.debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us", + rb_name.c_str(), + (uint64_t)latency_us, + (long)mean_pdu_latency_us.value()); #else - log->debug("%s Complete SDU scheduled for tx.\n", rb_name.c_str()); + logger.debug("%s Complete SDU scheduled for tx.", rb_name.c_str()); #endif tx_sdu.reset(); } @@ -211,7 +211,7 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* rlc_um_write_data_pdu_header(&header, pdu.get()); memcpy(payload, pdu->msg, pdu->N_bytes); - log->info_hex(payload, pdu->N_bytes, "%s Tx PDU SN=%d (%d B)\n", rb_name.c_str(), header.sn, pdu->N_bytes); + logger.info(payload, pdu->N_bytes, "%s Tx PDU SN=%d (%d B)", rb_name.c_str(), header.sn, pdu->N_bytes); debug_state(); @@ -220,7 +220,7 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* void rlc_um_lte::rlc_um_lte_tx::debug_state() { - log->debug("%s vt_us = %d\n", rb_name.c_str(), vt_us); + logger.debug("%s vt_us = %d", rb_name.c_str(), vt_us); } void rlc_um_lte::rlc_um_lte_tx::reset() @@ -243,13 +243,13 @@ bool rlc_um_lte::rlc_um_lte_rx::configure(const rlc_config_t& cnfg_, std::string cfg = cnfg_; if (cfg.um.rx_mod == 0) { - log->error("Error configuring %s RLC UM: rx_mod==0\n", rb_name.c_str()); + logger.error("Error configuring %s RLC UM: rx_mod==0", rb_name.c_str()); return false; } // check timer if (not reordering_timer.is_valid()) { - log->error("Configuring RLC UM RX: timers not configured\n"); + logger.error("Configuring RLC UM RX: timers not configured"); return false; } @@ -298,17 +298,17 @@ void rlc_um_lte::rlc_um_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b { rlc_umd_pdu_header_t header; rlc_um_read_data_pdu_header(payload, nof_bytes, cfg.um.rx_sn_field_length, &header); - log->info_hex(payload, nof_bytes, "%s Rx data PDU SN=%d (%d B)", rb_name.c_str(), header.sn, nof_bytes); + logger.info(payload, nof_bytes, "%s Rx data PDU SN=%d (%d B)", rb_name.c_str(), header.sn, nof_bytes); if (RX_MOD_BASE(header.sn) >= RX_MOD_BASE(vr_uh - cfg.um.rx_window_size) && RX_MOD_BASE(header.sn) < RX_MOD_BASE(vr_ur)) { - log->info("%s SN=%d outside rx window [%d:%d] - discarding\n", rb_name.c_str(), header.sn, vr_ur, vr_uh); + logger.info("%s SN=%d outside rx window [%d:%d] - discarding", rb_name.c_str(), header.sn, vr_ur, vr_uh); return; } std::map::iterator it = rx_window.find(header.sn); if (rx_window.end() != it) { - log->info("%s Discarding duplicate SN=%d\n", rb_name.c_str(), header.sn); + logger.info("%s Discarding duplicate SN=%d", rb_name.c_str(), header.sn); return; } @@ -316,7 +316,7 @@ void rlc_um_lte::rlc_um_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b rlc_umd_pdu_t pdu = {}; pdu.buf = make_byte_buffer(); if (!pdu.buf) { - log->error("Discarting packet: no space in buffer pool\n"); + logger.error("Discarting packet: no space in buffer pool"); return; } memcpy(pdu.buf->msg, payload, nof_bytes); @@ -334,9 +334,9 @@ void rlc_um_lte::rlc_um_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b } // Reassemble and deliver SDUs, while updating vr_ur - log->debug("Entering Reassemble from received PDU\n"); + logger.debug("Entering Reassemble from received PDU"); reassemble_rx_sdus(); - log->debug("Finished reassemble from received PDU\n"); + logger.debug("Finished reassemble from received PDU"); // Update reordering variables and timers if (reordering_timer.is_running()) { @@ -360,32 +360,32 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() if (!rx_sdu) { rx_sdu = make_byte_buffer(); if (!rx_sdu) { - log->error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().\n"); + logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus()."); return; } } // First catch up with lower edge of reordering window while (!inside_reordering_window(vr_ur)) { - log->debug("SN=%d is not inside reordering windows\n", vr_ur); + logger.debug("SN=%d is not inside reordering windows", vr_ur); if (rx_window.end() == rx_window.find(vr_ur)) { - log->debug("SN=%d not in rx_window. Reset received SDU\n", vr_ur); + logger.debug("SN=%d not in rx_window. Reset received SDU", vr_ur); rx_sdu->clear(); } else { // Handle any SDU segments for (uint32_t i = 0; i < rx_window[vr_ur].header.N_li; i++) { int len = rx_window[vr_ur].header.li[i]; - log->debug_hex(rx_window[vr_ur].buf->msg, - len, - "Handling segment %d/%d of length %d B of SN=%d\n", - i + 1, - rx_window[vr_ur].header.N_li, - len, - vr_ur); + logger.debug(rx_window[vr_ur].buf->msg, + len, + "Handling segment %d/%d of length %d B of SN=%d", + i + 1, + rx_window[vr_ur].header.N_li, + len, + vr_ur); // Check if we received a middle or end segment if (rx_sdu->N_bytes == 0 && i == 0 && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { - log->warning("Dropping PDU %d in reassembly due to lost start segment\n", vr_ur); + logger.warning("Dropping PDU %d in reassembly due to lost start segment", vr_ur); // Advance data pointers and continue with next segment rx_window[vr_ur].buf->msg += len; rx_window[vr_ur].buf->N_bytes -= len; @@ -400,18 +400,18 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() rx_window[vr_ur].buf->N_bytes -= len; if ((pdu_lost && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) || (vr_ur != ((vr_ur_in_rx_sdu + 1) % cfg.um.rx_mod))) { - log->warning("Dropping remainder of lost PDU (lower edge middle segments, vr_ur=%d, vr_ur_in_rx_sdu=%d)\n", - vr_ur, - vr_ur_in_rx_sdu); + logger.warning("Dropping remainder of lost PDU (lower edge middle segments, vr_ur=%d, vr_ur_in_rx_sdu=%d)", + vr_ur, + vr_ur_in_rx_sdu); rx_sdu->clear(); metrics.num_lost_pdus++; } else { - log->info_hex(rx_sdu->msg, - rx_sdu->N_bytes, - "%s Rx SDU vr_ur=%d, i=%d (lower edge middle segments)", - rb_name.c_str(), - vr_ur, - i); + logger.info(rx_sdu->msg, + rx_sdu->N_bytes, + "%s Rx SDU vr_ur=%d, i=%d (lower edge middle segments)", + rb_name.c_str(), + vr_ur, + i); rx_sdu->set_timestamp(); metrics.num_rx_sdus++; metrics.num_rx_sdu_bytes += rx_sdu->N_bytes; @@ -422,7 +422,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() } rx_sdu = make_byte_buffer(); if (!rx_sdu) { - log->error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().\n"); + logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus()."); return; } } @@ -431,21 +431,21 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() // Handle last segment if (rx_sdu->N_bytes > 0 || rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { - log->info("Writing last segment in SDU buffer. Lower edge vr_ur=%d, Buffer size=%d, segment size=%d\n", - vr_ur, - rx_sdu->N_bytes, - rx_window[vr_ur].buf->N_bytes); + logger.info("Writing last segment in SDU buffer. Lower edge vr_ur=%d, Buffer size=%d, segment size=%d", + vr_ur, + rx_sdu->N_bytes, + rx_window[vr_ur].buf->N_bytes); memcpy(&rx_sdu->msg[rx_sdu->N_bytes], rx_window[vr_ur].buf->msg, rx_window[vr_ur].buf->N_bytes); rx_sdu->N_bytes += rx_window[vr_ur].buf->N_bytes; vr_ur_in_rx_sdu = vr_ur; if (rlc_um_end_aligned(rx_window[vr_ur].header.fi)) { if (pdu_lost && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { - log->warning("Dropping remainder of lost PDU (lower edge last segments)\n"); + logger.warning("Dropping remainder of lost PDU (lower edge last segments)"); rx_sdu->clear(); metrics.num_lost_pdus++; } else { - log->info_hex( + logger.info( rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU vr_ur=%d (lower edge last segments)", rb_name.c_str(), vr_ur); rx_sdu->set_timestamp(); metrics.num_rx_sdus++; @@ -457,7 +457,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() } rx_sdu = make_byte_buffer(); if (!rx_sdu) { - log->error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().\n"); + logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus()."); return; } } @@ -474,11 +474,11 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() // Now update vr_ur until we reach an SN we haven't yet received while (rx_window.end() != rx_window.find(vr_ur)) { - log->debug("Reassemble loop for vr_ur=%d\n", vr_ur); + logger.debug("Reassemble loop for vr_ur=%d", vr_ur); if (not pdu_belongs_to_rx_sdu()) { - log->warning( - "PDU SN=%d lost, stop reassambling SDU (vr_ur_in_rx_sdu=%d)\n", vr_ur_in_rx_sdu + 1, vr_ur_in_rx_sdu); + logger.warning( + "PDU SN=%d lost, stop reassambling SDU (vr_ur_in_rx_sdu=%d)", vr_ur_in_rx_sdu + 1, vr_ur_in_rx_sdu); pdu_lost = false; // Reset flag to not prevent reassembling of further segments rx_sdu->clear(); } @@ -486,22 +486,22 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() // Handle any SDU segments for (uint32_t i = 0; i < rx_window[vr_ur].header.N_li; i++) { uint16_t len = rx_window[vr_ur].header.li[i]; - log->debug("Handling SDU segment i=%d with len=%d of vr_ur=%d N_li=%d [%s]\n", - i, - len, - vr_ur, - rx_window[vr_ur].header.N_li, - rlc_fi_field_text[rx_window[vr_ur].header.fi]); + logger.debug("Handling SDU segment i=%d with len=%d of vr_ur=%d N_li=%d [%s]", + i, + len, + vr_ur, + rx_window[vr_ur].header.N_li, + rlc_fi_field_text[rx_window[vr_ur].header.fi]); // Check if the first part of the PDU is a middle or end segment if (rx_sdu->N_bytes == 0 && i == 0 && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { - log->warning_hex( - rx_window[vr_ur].buf->msg, len, "Dropping first %d B of SN=%d due to lost start segment\n", len, vr_ur); + logger.warning( + rx_window[vr_ur].buf->msg, len, "Dropping first %d B of SN=%d due to lost start segment", len, vr_ur); if (rx_window[vr_ur].buf->N_bytes < len) { - log->error("Dropping remaining remainder of SN=%d too (N_bytes=%u < len=%d)\n", - vr_ur, - rx_window[vr_ur].buf->N_bytes, - len); + logger.error("Dropping remaining remainder of SN=%d too (N_bytes=%u < len=%d)", + vr_ur, + rx_window[vr_ur].buf->N_bytes, + len); goto clean_up_rx_window; } @@ -518,31 +518,31 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() // Check available space in SDU if ((uint32_t)len > rx_sdu->get_tailroom()) { - log->error("Dropping PDU %d due to buffer mis-alignment (current segment len %d B, received %d B)\n", - vr_ur, - rx_sdu->N_bytes, - len); + logger.error("Dropping PDU %d due to buffer mis-alignment (current segment len %d B, received %d B)", + vr_ur, + rx_sdu->N_bytes, + len); rx_sdu->clear(); metrics.num_lost_pdus++; goto clean_up_rx_window; } if (not pdu_belongs_to_rx_sdu()) { - log->info_hex(rx_window[vr_ur].buf->msg, len, "Copying first %d bytes of new SDU\n", len); - log->info("Updating vr_ur_in_rx_sdu. old=%d, new=%d\n", vr_ur_in_rx_sdu, vr_ur); + logger.info(rx_window[vr_ur].buf->msg, len, "Copying first %d bytes of new SDU", len); + logger.info("Updating vr_ur_in_rx_sdu. old=%d, new=%d", vr_ur_in_rx_sdu, vr_ur); vr_ur_in_rx_sdu = vr_ur; } else { - log->info_hex(rx_window[vr_ur].buf->msg, - len, - "Concatenating %d bytes in to current length %d. rx_window remaining bytes=%d, " - "vr_ur_in_rx_sdu=%d, vr_ur=%d, rx_mod=%d, last_mod=%d\n", - len, - rx_sdu->N_bytes, - rx_window[vr_ur].buf->N_bytes, - vr_ur_in_rx_sdu, - vr_ur, - cfg.um.rx_mod, - (vr_ur_in_rx_sdu + 1) % cfg.um.rx_mod); + logger.info(rx_window[vr_ur].buf->msg, + len, + "Concatenating %d bytes in to current length %d. rx_window remaining bytes=%d, " + "vr_ur_in_rx_sdu=%d, vr_ur=%d, rx_mod=%d, last_mod=%d", + len, + rx_sdu->N_bytes, + rx_window[vr_ur].buf->N_bytes, + vr_ur_in_rx_sdu, + vr_ur, + cfg.um.rx_mod, + (vr_ur_in_rx_sdu + 1) % cfg.um.rx_mod); } memcpy(&rx_sdu->msg[rx_sdu->N_bytes], rx_window[vr_ur].buf->msg, len); @@ -552,12 +552,12 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() vr_ur_in_rx_sdu = vr_ur; if (pdu_belongs_to_rx_sdu()) { - log->info_hex(rx_sdu->msg, - rx_sdu->N_bytes, - "%s Rx SDU vr_ur=%d, i=%d, (update vr_ur middle segments)", - rb_name.c_str(), - vr_ur, - i); + logger.info(rx_sdu->msg, + rx_sdu->N_bytes, + "%s Rx SDU vr_ur=%d, i=%d, (update vr_ur middle segments)", + rb_name.c_str(), + vr_ur, + i); rx_sdu->set_timestamp(); metrics.num_rx_sdus++; metrics.num_rx_sdu_bytes += rx_sdu->N_bytes; @@ -568,13 +568,13 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() } rx_sdu = make_byte_buffer(); if (!rx_sdu) { - log->error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().\n"); + logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus()."); return; } } else { - log->warning("Dropping remainder of lost PDU (update vr_ur middle segments, vr_ur=%d, vr_ur_in_rx_sdu=%d)\n", - vr_ur, - vr_ur_in_rx_sdu); + logger.warning("Dropping remainder of lost PDU (update vr_ur middle segments, vr_ur=%d, vr_ur_in_rx_sdu=%d)", + vr_ur, + vr_ur_in_rx_sdu); // Advance data pointers and continue with next segment rx_window[vr_ur].buf->msg += len; rx_window[vr_ur].buf->N_bytes -= len; @@ -586,7 +586,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() // Handle last segment if (rx_sdu->N_bytes == 0 && rx_window[vr_ur].header.N_li == 0 && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { - log->warning("Dropping PDU %d during last segment handling due to lost start segment\n", vr_ur); + logger.warning("Dropping PDU %d during last segment handling due to lost start segment", vr_ur); rx_sdu->clear(); metrics.num_lost_pdus++; goto clean_up_rx_window; @@ -595,30 +595,30 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() if (rx_sdu->N_bytes < SRSLTE_MAX_BUFFER_SIZE_BYTES && rx_window[vr_ur].buf->N_bytes < SRSLTE_MAX_BUFFER_SIZE_BYTES && rx_window[vr_ur].buf->N_bytes + rx_sdu->N_bytes < SRSLTE_MAX_BUFFER_SIZE_BYTES) { - log->info_hex(rx_window[vr_ur].buf->msg, - rx_window[vr_ur].buf->N_bytes, - "Writing last segment in SDU buffer. Updating vr_ur=%d, vr_ur_in_rx_sdu=%d, Buffer size=%d, " - "segment size=%d\n", - vr_ur, - vr_ur_in_rx_sdu, - rx_sdu->N_bytes, - rx_window[vr_ur].buf->N_bytes); + logger.info(rx_window[vr_ur].buf->msg, + rx_window[vr_ur].buf->N_bytes, + "Writing last segment in SDU buffer. Updating vr_ur=%d, vr_ur_in_rx_sdu=%d, Buffer size=%d, " + "segment size=%d", + vr_ur, + vr_ur_in_rx_sdu, + rx_sdu->N_bytes, + rx_window[vr_ur].buf->N_bytes); memcpy(&rx_sdu->msg[rx_sdu->N_bytes], rx_window[vr_ur].buf->msg, rx_window[vr_ur].buf->N_bytes); rx_sdu->N_bytes += rx_window[vr_ur].buf->N_bytes; } else { - log->error("Out of bounds while reassembling SDU buffer in UM: sdu_len=%d, window_buffer_len=%d, vr_ur=%d\n", - rx_sdu->N_bytes, - rx_window[vr_ur].buf->N_bytes, - vr_ur); + logger.error("Out of bounds while reassembling SDU buffer in UM: sdu_len=%d, window_buffer_len=%d, vr_ur=%d", + rx_sdu->N_bytes, + rx_window[vr_ur].buf->N_bytes, + vr_ur); } vr_ur_in_rx_sdu = vr_ur; if (rlc_um_end_aligned(rx_window[vr_ur].header.fi)) { if (pdu_lost && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { - log->warning("Dropping remainder of lost PDU (update vr_ur last segments)\n"); + logger.warning("Dropping remainder of lost PDU (update vr_ur last segments)"); rx_sdu->clear(); metrics.num_lost_pdus++; } else { - log->info_hex( + logger.info( rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU vr_ur=%d (update vr_ur last segments)", rb_name.c_str(), vr_ur); rx_sdu->set_timestamp(); metrics.num_rx_sdus++; @@ -630,7 +630,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus() } rx_sdu = make_byte_buffer(); if (!rx_sdu) { - log->error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().\n"); + logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus()."); return; } } @@ -677,9 +677,9 @@ void rlc_um_lte::rlc_um_lte_rx::timer_expired(uint32_t timeout_id) { if (reordering_timer.id() == timeout_id) { // 36.322 v10 Section 5.1.2.2.4 - log->info("%s reordering timeout expiry - updating vr_ur and reassembling\n", rb_name.c_str()); + logger.info("%s reordering timeout expiry - updating vr_ur and reassembling", rb_name.c_str()); - log->warning("Lost PDU SN=%d\n", vr_ur); + logger.warning("Lost PDU SN=%d", vr_ur); pdu_lost = true; if (rx_sdu != NULL) { @@ -688,9 +688,9 @@ void rlc_um_lte::rlc_um_lte_rx::timer_expired(uint32_t timeout_id) while (RX_MOD_BASE(vr_ur) < RX_MOD_BASE(vr_ux)) { vr_ur = (vr_ur + 1) % cfg.um.rx_mod; - log->debug("Entering Reassemble from timeout id=%d\n", timeout_id); + logger.debug("Entering Reassemble from timeout id=%d", timeout_id); reassemble_rx_sdus(); - log->debug("Finished reassemble from timeout id=%d\n", timeout_id); + logger.debug("Finished reassemble from timeout id=%d", timeout_id); } if (RX_MOD_BASE(vr_uh) > RX_MOD_BASE(vr_ur)) { @@ -708,7 +708,7 @@ void rlc_um_lte::rlc_um_lte_rx::timer_expired(uint32_t timeout_id) void rlc_um_lte::rlc_um_lte_rx::debug_state() { - log->debug("%s vr_ur = %d, vr_ux = %d, vr_uh = %d\n", rb_name.c_str(), vr_ur, vr_ux, vr_uh); + logger.debug("%s vr_ur = %d, vr_ux = %d, vr_uh = %d", rb_name.c_str(), vr_ur, vr_ux, vr_uh); } /**************************************************************************** diff --git a/lib/src/upper/rlc_um_nr.cc b/lib/src/upper/rlc_um_nr.cc index 59a8e6123..2996ec1a5 100644 --- a/lib/src/upper/rlc_um_nr.cc +++ b/lib/src/upper/rlc_um_nr.cc @@ -17,12 +17,12 @@ namespace srslte { -rlc_um_nr::rlc_um_nr(srslte::log_ref log_, +rlc_um_nr::rlc_um_nr(srslog::basic_logger& logger, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_, srslte::timer_handler* timers_) : - rlc_um_base(log_, lcid_, pdcp_, rrc_, timers_) + rlc_um_base(logger, lcid_, pdcp_, rrc_, timers_) {} rlc_um_nr::~rlc_um_nr() @@ -48,10 +48,10 @@ bool rlc_um_nr::configure(const rlc_config_t& cnfg_) return false; } - log->info("%s configured in %s: sn_field_length=%u bits\n", - rb_name.c_str(), - srslte::to_string(cnfg_.rlc_mode).c_str(), - srslte::to_number(cfg.um_nr.sn_field_length)); + logger.info("%s configured in %s: sn_field_length=%u bits", + rb_name.c_str(), + srslte::to_string(cnfg_.rlc_mode).c_str(), + srslte::to_number(cfg.um_nr.sn_field_length)); rx_enabled = true; tx_enabled = true; @@ -94,7 +94,7 @@ bool rlc_um_nr::rlc_um_nr_tx::configure(const rlc_config_t& cnfg_, std::string r cfg = cnfg_; if (cfg.um_nr.mod == 0) { - log->error("Error configuring %s RLC UM: tx_mod==0\n", rb_name.c_str()); + logger.error("Error configuring %s RLC UM: tx_mod==0", rb_name.c_str()); return false; } @@ -120,10 +120,10 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p int pdu_space = SRSLTE_MIN(nof_bytes, pdu->get_tailroom()); if (pdu_space <= head_len + 1) { - log->warning("%s Cannot build a PDU - %d bytes available, %d bytes required for header\n", - rb_name.c_str(), - nof_bytes, - head_len); + logger.warning("%s Cannot build a PDU - %d bytes available, %d bytes required for header", + rb_name.c_str(), + nof_bytes, + head_len); return 0; } @@ -131,17 +131,16 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p if (tx_sdu) { uint32_t space = pdu_space - head_len; to_move = space >= tx_sdu->N_bytes ? tx_sdu->N_bytes : space; - log->debug( - "%s adding remainder of SDU segment - %d bytes of %d remaining\n", rb_name.c_str(), to_move, tx_sdu->N_bytes); + logger.debug( + "%s adding remainder of SDU segment - %d bytes of %d remaining", rb_name.c_str(), to_move, tx_sdu->N_bytes); memcpy(pdu_ptr, tx_sdu->msg, to_move); pdu_ptr += to_move; pdu->N_bytes += to_move; tx_sdu->N_bytes -= to_move; tx_sdu->msg += to_move; if (tx_sdu->N_bytes == 0) { - log->debug("%s Complete SDU scheduled for tx. Stack latency: %ld us\n", - rb_name.c_str(), - tx_sdu->get_latency_us().count()); + logger.debug( + "%s Complete SDU scheduled for tx. Stack latency: %ld us", rb_name.c_str(), tx_sdu->get_latency_us().count()); tx_sdu.reset(); header.si = rlc_nr_si_field_t::last_segment; } else { @@ -151,22 +150,21 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p header.so = next_so; } else { // Pull SDU from queue - log->debug("pdu_space=%d, head_len=%d\n", pdu_space, head_len); + logger.debug("pdu_space=%d, head_len=%d", pdu_space, head_len); head_len = rlc_um_nr_packed_length(header); tx_sdu = tx_sdu_queue.read(); uint32_t space = pdu_space - head_len; to_move = space >= tx_sdu->N_bytes ? tx_sdu->N_bytes : space; - log->debug("%s adding new SDU - %d bytes of %d remaining\n", rb_name.c_str(), to_move, tx_sdu->N_bytes); + logger.debug("%s adding new SDU - %d bytes of %d remaining", rb_name.c_str(), to_move, tx_sdu->N_bytes); memcpy(pdu_ptr, tx_sdu->msg, to_move); pdu_ptr += to_move; pdu->N_bytes += to_move; tx_sdu->N_bytes -= to_move; tx_sdu->msg += to_move; if (tx_sdu->N_bytes == 0) { - log->debug("%s Complete SDU scheduled for tx. Stack latency: %ld us\n", - rb_name.c_str(), - tx_sdu->get_latency_us().count()); + logger.debug( + "%s Complete SDU scheduled for tx. Stack latency: %ld us", rb_name.c_str(), tx_sdu->get_latency_us().count()); tx_sdu.reset(); header.si = rlc_nr_si_field_t::full_sdu; } else { @@ -189,7 +187,7 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p memcpy(payload, pdu->msg, pdu->N_bytes); uint32_t ret = pdu->N_bytes; - log->info_hex(payload, ret, "%s Tx PDU SN=%d (%d B)\n", rb_name.c_str(), header.sn, pdu->N_bytes); + logger.info(payload, ret, "%s Tx PDU SN=%d (%d B)", rb_name.c_str(), header.sn, pdu->N_bytes); debug_state(); @@ -198,7 +196,7 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p void rlc_um_nr::rlc_um_nr_tx::debug_state() { - log->debug("%s TX_Next=%d, next_so=%d\n", rb_name.c_str(), TX_Next, next_so); + logger.debug("%s TX_Next=%d, next_so=%d", rb_name.c_str(), TX_Next, next_so); } void rlc_um_nr::rlc_um_nr_tx::reset() @@ -218,13 +216,13 @@ rlc_um_nr::rlc_um_nr_rx::rlc_um_nr_rx(rlc_um_base* parent_) : bool rlc_um_nr::rlc_um_nr_rx::configure(const rlc_config_t& cnfg_, std::string rb_name_) { if (cfg.um_nr.mod == 0) { - log->error("Error configuring %s RLC UM: rx_mod==0\n", rb_name.c_str()); + logger.error("Error configuring %s RLC UM: rx_mod==0", rb_name.c_str()); return false; } // check timer if (not reassembly_timer.is_valid()) { - log->error("Configuring RLC UM NR RX: timers not configured\n"); + logger.error("Configuring RLC UM NR RX: timers not configured"); return false; } @@ -273,9 +271,9 @@ void rlc_um_nr::rlc_um_nr_rx::timer_expired(uint32_t timeout_id) { std::lock_guard lock(mutex); if (reassembly_timer.id() == timeout_id) { - log->info("%s reassembly timeout expiry - updating RX_Next_Reassembly and reassembling\n", rb_name.c_str()); + logger.info("%s reassembly timeout expiry - updating RX_Next_Reassembly and reassembling", rb_name.c_str()); - log->warning("Lost PDU SN: %d\n", RX_Next_Reassembly); + logger.warning("Lost PDU SN: %d", RX_Next_Reassembly); metrics.num_lost_pdus++; if (rx_sdu != nullptr) { @@ -330,7 +328,7 @@ unique_byte_buffer_t rlc_um_nr::rlc_um_nr_rx::rlc_um_nr_strip_pdu_header(const r { unique_byte_buffer_t sdu = make_byte_buffer(); if (!sdu) { - log->error("Discarting packet: no space in buffer pool\n"); + logger.error("Discarting packet: no space in buffer pool"); return nullptr; } memcpy(sdu->msg, payload, nof_bytes); @@ -357,32 +355,32 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn) // iterate over received segments and try to assemble full SDU auto& pdu = rx_window.at(sn); for (auto it = pdu.segments.begin(); it != pdu.segments.end();) { - log->debug("Have %s segment with SO=%d for SN=%d\n", - to_string_short(it->second.header.si).c_str(), - it->second.header.so, - it->second.header.sn); + logger.debug("Have %s segment with SO=%d for SN=%d", + to_string_short(it->second.header.si).c_str(), + it->second.header.so, + it->second.header.sn); if (it->second.header.so == pdu.next_expected_so) { if (pdu.next_expected_so == 0) { if (pdu.sdu == nullptr) { // reuse buffer of first segment for final SDU pdu.sdu = std::move(it->second.buf); pdu.next_expected_so = pdu.sdu->N_bytes; - log->debug("Reusing first segment of SN=%d for final SDU\n", it->second.header.sn); + logger.debug("Reusing first segment of SN=%d for final SDU", it->second.header.sn); it = pdu.segments.erase(it); } else { - log->debug("SDU buffer already allocated. Possible retransmission of first segment.\n"); + logger.debug("SDU buffer already allocated. Possible retransmission of first segment."); if (it->second.header.so != pdu.next_expected_so) { - log->error("Invalid PDU. SO doesn't match. Discarting all segments of SN=%d.\n", sn); + logger.error("Invalid PDU. SO doesn't match. Discarting all segments of SN=%d.", sn); rx_window.erase(sn); return; } } } else { if (it->second.buf->N_bytes > pdu.sdu->get_tailroom()) { - log->error("Cannot fit RLC PDU in SDU buffer (tailroom=%d, len=%d), dropping both. Erasing SN=%d.\n", - rx_sdu->get_tailroom(), - it->second.buf->N_bytes, - it->second.header.sn); + logger.error("Cannot fit RLC PDU in SDU buffer (tailroom=%d, len=%d), dropping both. Erasing SN=%d.", + rx_sdu->get_tailroom(), + it->second.buf->N_bytes, + it->second.header.sn); rx_window.erase(sn); metrics.num_lost_pdus++; return; @@ -392,12 +390,12 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn) memcpy(pdu.sdu->msg + pdu.sdu->N_bytes, it->second.buf->msg, it->second.buf->N_bytes); pdu.sdu->N_bytes += it->second.buf->N_bytes; pdu.next_expected_so += it->second.buf->N_bytes; - log->debug("Appended SO=%d of SN=%d\n", it->second.header.so, it->second.header.sn); + logger.debug("Appended SO=%d of SN=%d", it->second.header.so, it->second.header.sn); it = pdu.segments.erase(it); if (pdu.next_expected_so == pdu.total_sdu_length) { // deliver full SDU to upper layers - log->info("Delivering %s SDU SN=%d (%d B)", rb_name.c_str(), sn, pdu.sdu->N_bytes); + logger.info("Delivering %s SDU SN=%d (%d B)", rb_name.c_str(), sn, pdu.sdu->N_bytes); pdcp->write_pdu(lcid, std::move(pdu.sdu)); // find next SN in rx buffer @@ -406,7 +404,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn) while (RX_MOD_NR_BASE(RX_Next_Reassembly) < RX_MOD_NR_BASE(RX_Next_Highest)) { RX_Next_Reassembly = (RX_Next_Reassembly + 1) % cfg.um_nr.mod; } - log->debug("Updating RX_Next_Reassembly=%d\n", RX_Next_Reassembly); + logger.debug("Updating RX_Next_Reassembly=%d", RX_Next_Reassembly); } // delete PDU from rx_window @@ -424,16 +422,16 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn) if (not sn_in_reassembly_window(sn)) { // update RX_Next_highest RX_Next_Highest = sn + 1; - log->debug("Updating RX_Next_Highest=%d\n", RX_Next_Highest); + logger.debug("Updating RX_Next_Highest=%d", RX_Next_Highest); // drop all SNs outside of new rx window for (auto it = rx_window.begin(); it != rx_window.end();) { if (not sn_in_reassembly_window(it->first)) { - log->info("%s SN: %d outside rx window [%d:%d] - discarding\n", - rb_name.c_str(), - it->first, - RX_Next_Highest - cfg.um_nr.UM_Window_Size, - RX_Next_Highest); + logger.info("%s SN: %d outside rx window [%d:%d] - discarding", + rb_name.c_str(), + it->first, + RX_Next_Highest - cfg.um_nr.UM_Window_Size, + RX_Next_Highest); it = rx_window.erase(it); metrics.num_lost_pdus++; } else { @@ -446,7 +444,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn) for (const auto& rx_pdu : rx_window) { if (rx_pdu.first >= RX_MOD_NR_BASE(RX_Next_Highest - cfg.um_nr.UM_Window_Size)) { RX_Next_Reassembly = rx_pdu.first; - log->debug("Updating RX_Next_Reassembly=%d\n", RX_Next_Reassembly); + logger.debug("Updating RX_Next_Reassembly=%d", RX_Next_Reassembly); break; } } @@ -468,7 +466,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn) } } } else { - log->error("SN=%d does not exist in Rx buffer\n", sn); + logger.error("SN=%d does not exist in Rx buffer", sn); } } @@ -477,10 +475,10 @@ inline void rlc_um_nr::rlc_um_nr_rx::update_total_sdu_length(rlc_umd_pdu_segment { if (rx_pdu.header.si == rlc_nr_si_field_t::last_segment) { pdu_segments.total_sdu_length = rx_pdu.header.so + rx_pdu.buf->N_bytes; - log->info("%s updating total SDU length for SN=%d to %d B\n", - rb_name.c_str(), - rx_pdu.header.sn, - pdu_segments.total_sdu_length); + logger.info("%s updating total SDU length for SN=%d to %d B", + rb_name.c_str(), + rx_pdu.header.sn, + pdu_segments.total_sdu_length); } }; @@ -491,7 +489,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_byt rlc_um_nr_pdu_header_t header = {}; rlc_um_nr_read_data_pdu_header(payload, nof_bytes, cfg.um_nr.sn_field_length, &header); - log->debug_hex(payload, nof_bytes, "RX %s Rx data PDU (%d B)", rb_name.c_str(), nof_bytes); + logger.debug(payload, nof_bytes, "RX %s Rx data PDU (%d B)", rb_name.c_str(), nof_bytes); // check if PDU contains a SN if (header.si == rlc_nr_si_field_t::full_sdu) { @@ -499,10 +497,10 @@ void rlc_um_nr::rlc_um_nr_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_byt unique_byte_buffer_t sdu = rlc_um_nr_strip_pdu_header(header, payload, nof_bytes); // deliver to PDCP - log->info("Delivering %s SDU (%d B)", rb_name.c_str(), sdu->N_bytes); + logger.info("Delivering %s SDU (%d B)", rb_name.c_str(), sdu->N_bytes); pdcp->write_pdu(lcid, std::move(sdu)); } else if (sn_invalid_for_rx_buffer(header.sn)) { - log->info("%s Discarding SN=%d\n", rb_name.c_str(), header.sn); + logger.info("%s Discarding SN=%d", rb_name.c_str(), header.sn); // Nothing else to do here .. } else { // place PDU in receive buffer @@ -513,21 +511,21 @@ void rlc_um_nr::rlc_um_nr_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_byt // check if this SN is already present in rx buffer if (rx_window.find(header.sn) == rx_window.end()) { // first received segment of this SN, add to rx buffer - log->info("%s placing %s segment of SN=%d in Rx buffer\n", - rb_name.c_str(), - to_string_short(header.si).c_str(), - header.sn); + logger.info("%s placing %s segment of SN=%d in Rx buffer", + rb_name.c_str(), + to_string_short(header.si).c_str(), + header.sn); rlc_umd_pdu_segments_nr_t pdu_segments = {}; update_total_sdu_length(pdu_segments, rx_pdu); pdu_segments.segments.emplace(header.so, std::move(rx_pdu)); rx_window[header.sn] = std::move(pdu_segments); } else { // other segment for this SN already present, update received data - log->info("%s updating SN=%d at SO=%d with %d B\n", - rb_name.c_str(), - rx_pdu.header.sn, - rx_pdu.header.so, - rx_pdu.buf->N_bytes); + logger.info("%s updating SN=%d at SO=%d with %d B", + rb_name.c_str(), + rx_pdu.header.sn, + rx_pdu.header.so, + rx_pdu.buf->N_bytes); auto& pdu_segments = rx_window.at(header.sn); @@ -547,12 +545,12 @@ void rlc_um_nr::rlc_um_nr_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_byt void rlc_um_nr::rlc_um_nr_rx::debug_state() { - log->debug("%s RX_Next_Reassembly=%d, RX_Timer_Trigger=%d, RX_Next_Highest=%d, t_Reassembly=%s\n", - rb_name.c_str(), - RX_Next_Reassembly, - RX_Timer_Trigger, - RX_Next_Highest, - reassembly_timer.is_running() ? "running" : "stopped"); + logger.debug("%s RX_Next_Reassembly=%d, RX_Timer_Trigger=%d, RX_Next_Highest=%d, t_Reassembly=%s", + rb_name.c_str(), + RX_Next_Reassembly, + RX_Timer_Trigger, + RX_Next_Highest, + reassembly_timer.is_running() ? "running" : "stopped"); } /**************************************************************************** * Header pack/unpack helper functions @@ -593,7 +591,7 @@ uint32_t rlc_um_nr_read_data_pdu_header(const uint8_t* payload, if (header->si == rlc_nr_si_field_t::first_segment) { // make sure two reserved bits are not set if (((*ptr >> 4) & 0x03) != 0) { - fprintf(stderr, "Malformed PDU, reserved bits are set.\n"); + fprintf(stderr, "Malformed PDU, reserved bits are set."); return 0; } } diff --git a/lib/test/upper/rlc_am_control_test.cc b/lib/test/upper/rlc_am_control_test.cc index 7c81fc337..984fa09e5 100644 --- a/lib/test/upper/rlc_am_control_test.cc +++ b/lib/test/upper/rlc_am_control_test.cc @@ -64,6 +64,8 @@ int status_pdu_with_nacks_test1() int main(int argc, char** argv) { + srslog::init(); + TESTASSERT(simple_status_pdu_test1() == SRSLTE_SUCCESS); TESTASSERT(status_pdu_with_nacks_test1() == SRSLTE_SUCCESS); diff --git a/lib/test/upper/rlc_am_data_test.cc b/lib/test/upper/rlc_am_data_test.cc index d3b1da428..134cd07ad 100644 --- a/lib/test/upper/rlc_am_data_test.cc +++ b/lib/test/upper/rlc_am_data_test.cc @@ -143,9 +143,12 @@ int test4() int main(int argc, char** argv) { + srslog::init(); + TESTASSERT(test1() == SRSLTE_SUCCESS); TESTASSERT(test2() == SRSLTE_SUCCESS); TESTASSERT(test3() == SRSLTE_SUCCESS); TESTASSERT(test4() == SRSLTE_SUCCESS); + return SRSLTE_SUCCESS; } diff --git a/lib/test/upper/rlc_am_nr_pdu_test.cc b/lib/test/upper/rlc_am_nr_pdu_test.cc index 9d359c010..f3c6e828e 100644 --- a/lib/test/upper/rlc_am_nr_pdu_test.cc +++ b/lib/test/upper/rlc_am_nr_pdu_test.cc @@ -292,6 +292,8 @@ int main(int argc, char** argv) pcap_handle->open("rlc_am_nr_pdu_test.pcap"); #endif + srslog::init(); + if (rlc_am_nr_pdu_test1()) { fprintf(stderr, "rlc_am_nr_pdu_test1() failed.\n"); return SRSLTE_ERROR; diff --git a/lib/test/upper/rlc_am_test.cc b/lib/test/upper/rlc_am_test.cc index 18cee5056..86caa2273 100644 --- a/lib/test/upper/rlc_am_test.cc +++ b/lib/test/upper/rlc_am_test.cc @@ -23,9 +23,6 @@ using namespace srsue; using namespace srslte; -srslte::log_ref rrc_log1("RLC_AM_1"); -srslte::log_ref rrc_log2("RLC_AM_2"); - bool rx_is_tx(const rlc_bearer_metrics_t& rlc1_metrics, const rlc_bearer_metrics_t& rlc2_metrics) { if (rlc1_metrics.num_tx_pdu_bytes != rlc2_metrics.num_rx_pdu_bytes) { @@ -154,8 +151,8 @@ int basic_test() timer_handler timers(8); byte_buffer_t pdu_bufs[NBUFS]; - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); // before configuring entity TESTASSERT(0 == rlc1.get_buffer_state()); @@ -211,8 +208,8 @@ int concat_test() rlc_am_tester tester; srslte::timer_handler timers(8); - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -287,8 +284,8 @@ int segment_test(bool in_seq_rx) srslte::timer_handler timers(8); int len = 0; - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -382,8 +379,8 @@ int retx_test() timer_handler timers(8); int len = 0; - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -518,8 +515,8 @@ int segment_retx_test() timer_handler timers(8); int len = 0; - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -642,8 +639,8 @@ int resegment_test_1() timer_handler timers(8); int len = 0; - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -707,7 +704,7 @@ int resegment_test_1() TESTASSERT(12 == rlc1.get_buffer_state()); // 2 byte header + 10 data // Check notifications - rrc_log1->debug("%ld\n", tester.notified_counts.size()); + srslog::fetch_basic_logger("RLC_AM_1").debug("%ld", tester.notified_counts.size()); TESTASSERT(tester.notified_counts.size() == 4); for (int i = 0; i < 5; i++) { auto it = tester.notified_counts.find(i); @@ -801,8 +798,8 @@ int resegment_test_2() timer_handler timers(8); int len = 0; - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -934,8 +931,8 @@ int resegment_test_3() rlc_am_tester tester; srslte::timer_handler timers(8); - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -1065,8 +1062,8 @@ int resegment_test_4() rlc_am_tester tester; srslte::timer_handler timers(8); - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -1198,8 +1195,8 @@ int resegment_test_5() rlc_am_tester tester; srslte::timer_handler timers(8); - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -1326,8 +1323,8 @@ int resegment_test_6() srslte::timer_handler timers(8); int len = 0; - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -1497,8 +1494,8 @@ int resegment_test_7() #endif srslte::timer_handler timers(8); - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -1685,8 +1682,8 @@ int resegment_test_8() #endif srslte::timer_handler timers(8); - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -1827,7 +1824,7 @@ bool reset_test() srslte::timer_handler timers(8); int len = 0; - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -1869,7 +1866,7 @@ bool resume_test() srslte::timer_handler timers(8); int len = 0; - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -1910,7 +1907,7 @@ bool stop_test() rlc_am_tester tester; srslte::timer_handler timers(8); - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -1937,8 +1934,8 @@ bool status_pdu_test() srslte::timer_handler timers(8); int len = 0; - rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); - rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); + rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers); + rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers); if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { return -1; @@ -2049,10 +2046,14 @@ bool status_pdu_test() int main(int argc, char** argv) { - rrc_log1->set_level(srslte::LOG_LEVEL_DEBUG); - rrc_log2->set_level(srslte::LOG_LEVEL_DEBUG); - rrc_log1->set_hex_limit(-1); - rrc_log2->set_hex_limit(-1); + srslog::init(); + + auto& logger_rrc1 = srslog::fetch_basic_logger("RLC_AM_1", false); + logger_rrc1.set_level(srslog::basic_levels::debug); + logger_rrc1.set_hex_dump_max_size(-1); + auto& logger_rrc2 = srslog::fetch_basic_logger("RLC_AM_2", false); + logger_rrc2.set_level(srslog::basic_levels::debug); + logger_rrc2.set_hex_dump_max_size(-1); if (basic_test()) { printf("basic_test failed\n"); @@ -2114,8 +2115,8 @@ int main(int argc, char** argv) exit(-1); }; - rrc_log1->set_hex_limit(100); - rrc_log2->set_hex_limit(100); + logger_rrc1.set_hex_dump_max_size(100); + logger_rrc2.set_hex_dump_max_size(100); if (resegment_test_7()) { printf("resegment_test_7 failed\n"); exit(-1); @@ -2125,8 +2126,8 @@ int main(int argc, char** argv) printf("resegment_test_8 failed\n"); exit(-1); }; - rrc_log1->set_hex_limit(-1); - rrc_log2->set_hex_limit(-1); + logger_rrc1.set_hex_dump_max_size(-1); + logger_rrc2.set_hex_dump_max_size(-1); if (reset_test()) { printf("reset_test failed\n"); diff --git a/lib/test/upper/rlc_common_test.cc b/lib/test/upper/rlc_common_test.cc index f9ae76f65..d1079854a 100644 --- a/lib/test/upper/rlc_common_test.cc +++ b/lib/test/upper/rlc_common_test.cc @@ -64,19 +64,20 @@ public: int meas_obj_test() { - srslte::log_ref log1("RLC_1"); - srslte::log_ref log2("RLC_2"); - log1->set_level(srslte::LOG_LEVEL_DEBUG); - log2->set_level(srslte::LOG_LEVEL_DEBUG); - log1->set_hex_limit(-1); - log2->set_hex_limit(-1); + auto& logger_rlc1 = srslog::fetch_basic_logger("RLC_1", false); + logger_rlc1.set_level(srslog::basic_levels::debug); + logger_rlc1.set_hex_dump_max_size(-1); + auto& logger_rlc2 = srslog::fetch_basic_logger("RLC_2", false); + logger_rlc2.set_level(srslog::basic_levels::debug); + logger_rlc2.set_hex_dump_max_size(-1); + rlc_tester tester; srslte::timer_handler timers(1); int len = 0; - rlc rlc1(log1->get_service_name().c_str()); - rlc rlc2(log2->get_service_name().c_str()); + rlc rlc1(logger_rlc1.id().c_str()); + rlc rlc2(logger_rlc2.id().c_str()); rlc1.init(&tester, &tester, &timers, 0); rlc2.init(&tester, &tester, &timers, 0); @@ -195,6 +196,8 @@ int meas_obj_test() int main(int argc, char** argv) { + srslog::init(); + if (meas_obj_test()) { return -1; } diff --git a/lib/test/upper/rlc_stress_test.cc b/lib/test/upper/rlc_stress_test.cc index 5bcb7c4a2..c7cc8d2df 100644 --- a/lib/test/upper/rlc_stress_test.cc +++ b/lib/test/upper/rlc_stress_test.cc @@ -153,14 +153,14 @@ public: pcap(pcap_), lcid(lcid_), timers(timers_), - log("MAC "), + logger(srslog::fetch_basic_logger("MAC", false)), thread("MAC_DUMMY"), real_dist(0.0, 1.0), mt19937(1234), pool(byte_buffer_pool::get_instance()) { - log.set_level(static_cast(args.log_level)); - log.set_hex_limit(LOG_HEX_LIMIT); + logger.set_level(static_cast(args.log_level)); + logger.set_hex_dump_max_size(LOG_HEX_LIMIT); } void stop() @@ -227,7 +227,7 @@ private: // Cut if ((real_dist(mt19937) < args.pdu_cut_rate)) { int cut_pdu_len = static_cast(pdu_len * real_dist(mt19937)); - log.info("Cutting MAC PDU len (%d B -> %d B)\n", pdu_len, cut_pdu_len); + logger.info("Cutting MAC PDU len (%d B -> %d B)", pdu_len, cut_pdu_len); pdu_len = cut_pdu_len; } @@ -242,7 +242,7 @@ private: pcap->write_ul_ccch(pdu->msg, pdu_len); } } else { - log.warning_hex(pdu->msg, pdu->N_bytes, "Dropping RLC PDU (%d B)\n", pdu->N_bytes); + logger.warning(pdu->msg, pdu->N_bytes, "Dropping RLC PDU (%d B)", pdu->N_bytes); skip_action = true; // Avoid drop duplicating this PDU } @@ -251,7 +251,7 @@ private: it++; skip_action = false; // Allow action on the next PDU } else { - log.warning_hex(pdu->msg, pdu->N_bytes, "Duplicating RLC PDU (%d B)\n", pdu->N_bytes); + logger.warning(pdu->msg, pdu->N_bytes, "Duplicating RLC PDU (%d B)", pdu->N_bytes); skip_action = true; // Avoid drop of this PDU } } @@ -300,7 +300,7 @@ private: stress_test_args_t args; rlc_pcap* pcap; uint32_t lcid; - srslte::log_filter log; + srslog::basic_logger& logger; srslte::timer_handler* timers = nullptr; srslte::block_queue pending_tasks; @@ -314,10 +314,18 @@ class rlc_tester : public pdcp_interface_rlc, public rrc_interface_rlc, public t { public: rlc_tester(rlc_interface_pdcp* rlc_, std::string name_, stress_test_args_t args_, uint32_t lcid_) : - log("TEST"), rlc(rlc_), run_enable(true), rx_pdus(), name(name_), args(args_), lcid(lcid_), thread("RLC_TESTER") + log("TEST"), + logger(srslog::fetch_basic_logger("TEST", false)), + rlc(rlc_), + run_enable(true), + rx_pdus(), + name(name_), + args(args_), + lcid(lcid_), + thread("RLC_TESTER") { - log.set_level(srslte::LOG_LEVEL_ERROR); - log.set_hex_limit(LOG_HEX_LIMIT); + logger.set_level(srslog::basic_levels::error); + logger.set_hex_dump_max_size(LOG_HEX_LIMIT); } void stop() @@ -331,7 +339,7 @@ public: { assert(rx_lcid == lcid); if (sdu->N_bytes != args.sdu_size) { - log.error_hex(sdu->msg, sdu->N_bytes, "Received SDU with size %d, expected %d.\n", sdu->N_bytes, args.sdu_size); + logger.error(sdu->msg, sdu->N_bytes, "Received SDU with size %d, expected %d.", sdu->N_bytes, args.sdu_size); if (args.pedantic_sdu_check) { exit(-1); } @@ -377,10 +385,11 @@ private: } } - bool run_enable; - uint64_t rx_pdus; - uint32_t lcid; - srslte::log_filter log; + bool run_enable; + uint64_t rx_pdus; + uint32_t lcid; + srslte::log_filter log; + srslog::basic_logger& logger; std::string name; @@ -391,12 +400,13 @@ private: void stress_test(stress_test_args_t args) { - srslte::log_ref log1("RLC_1"); - srslte::log_ref log2("RLC_2"); - log1->set_level(static_cast(args.log_level)); - log2->set_level(static_cast(args.log_level)); - log1->set_hex_limit(LOG_HEX_LIMIT); - log2->set_hex_limit(LOG_HEX_LIMIT); + auto& log1 = srslog::fetch_basic_logger("RLC_1", false); + log1.set_level(static_cast(args.log_level)); + log1.set_hex_dump_max_size(LOG_HEX_LIMIT); + auto& log2 = srslog::fetch_basic_logger("RLC_2", false); + log2.set_level(static_cast(args.log_level)); + log2.set_hex_dump_max_size(LOG_HEX_LIMIT); + rlc_pcap pcap; uint32_t lcid = 1; @@ -455,8 +465,8 @@ void stress_test(stress_test_args_t args) srslte::timer_handler timers(8); - rlc rlc1(log1->get_service_name().c_str()); - rlc rlc2(log2->get_service_name().c_str()); + rlc rlc1(log1.id().c_str()); + rlc rlc2(log2.id().c_str()); rlc_tester tester1(&rlc1, "tester1", args, lcid); rlc_tester tester2(&rlc2, "tester2", args, lcid); @@ -539,6 +549,8 @@ int main(int argc, char** argv) stress_test_args_t args = {}; parse_args(&args, argc, argv); + srslog::init(); + if (args.zero_seed) { srand(0); } else { diff --git a/lib/test/upper/rlc_um_data_test.cc b/lib/test/upper/rlc_um_data_test.cc index 03d9f0462..c68c3fbe1 100644 --- a/lib/test/upper/rlc_um_data_test.cc +++ b/lib/test/upper/rlc_um_data_test.cc @@ -24,6 +24,8 @@ uint32_t PDU2_LEN = 4; int main(int argc, char** argv) { + srslog::init(); + srslte::rlc_umd_pdu_header_t h; srslte::byte_buffer_t b1, b2; diff --git a/lib/test/upper/rlc_um_nr_pdu_test.cc b/lib/test/upper/rlc_um_nr_pdu_test.cc index 5d4c0fc03..e71c74930 100644 --- a/lib/test/upper/rlc_um_nr_pdu_test.cc +++ b/lib/test/upper/rlc_um_nr_pdu_test.cc @@ -202,6 +202,8 @@ int main(int argc, char** argv) pcap_handle->open("rlc_um_nr_pdu_test.pcap"); #endif + srslog::init(); + if (rlc_um_nr_pdu_test1()) { fprintf(stderr, "rlc_um_nr_pdu_test1() failed.\n"); return SRSLTE_ERROR; diff --git a/lib/test/upper/rlc_um_nr_test.cc b/lib/test/upper/rlc_um_nr_test.cc index 8b2bae36f..36fd725b5 100644 --- a/lib/test/upper/rlc_um_nr_test.cc +++ b/lib/test/upper/rlc_um_nr_test.cc @@ -72,17 +72,17 @@ class rlc_um_nr_test_context1 { public: rlc_um_nr_test_context1() : - log1("RLC_UM_1"), - log2("RLC_UM_2"), + logger1(srslog::fetch_basic_logger("RLC_UM_1", false)), + logger2(srslog::fetch_basic_logger("RLC_UM_2", false)), timers(16), - rlc1(log1, 3, &tester, &tester, &timers), - rlc2(log2, 3, &tester, &tester, &timers) + rlc1(logger1, 3, &tester, &tester, &timers), + rlc2(logger2, 3, &tester, &tester, &timers) { // setup logging - log1->set_level(srslte::LOG_LEVEL_DEBUG); - log2->set_level(srslte::LOG_LEVEL_DEBUG); - log1->set_hex_limit(-1); - log2->set_hex_limit(-1); + logger1.set_level(srslog::basic_levels::debug); + logger1.set_hex_dump_max_size(-1); + logger2.set_level(srslog::basic_levels::debug); + logger2.set_hex_dump_max_size(-1); // configure RLC entities rlc_config_t cnfg = rlc_config_t::default_rlc_um_nr_config(6); @@ -96,7 +96,8 @@ public: tester.set_expected_sdu_len(1); } - srslte::log_ref log1, log2; + srslog::basic_logger& logger1; + srslog::basic_logger& logger2; srslte::timer_handler timers; rlc_um_tester tester; rlc_um_nr rlc1, rlc2; @@ -561,6 +562,8 @@ int main(int argc, char** argv) pcap_handle->open("rlc_um_nr_test.pcap"); #endif + srslog::init(); + if (rlc_um_nr_test1()) { fprintf(stderr, "rlc_um_nr_test1() failed.\n"); return SRSLTE_ERROR; diff --git a/lib/test/upper/rlc_um_test.cc b/lib/test/upper/rlc_um_test.cc index fe2032a95..5ff376e6a 100644 --- a/lib/test/upper/rlc_um_test.cc +++ b/lib/test/upper/rlc_um_test.cc @@ -34,17 +34,17 @@ class rlc_um_lte_test_context1 { public: rlc_um_lte_test_context1() : - log1("RLC_UM_1"), - log2("RLC_UM_2"), + logger1(srslog::fetch_basic_logger("RLC_UM_1", false)), + logger2(srslog::fetch_basic_logger("RLC_UM_2", false)), timers(16), - rlc1(log1, 3, &tester, &tester, &timers), - rlc2(log2, 3, &tester, &tester, &timers) + rlc1(logger1, 3, &tester, &tester, &timers), + rlc2(logger2, 3, &tester, &tester, &timers) { // setup logging - log1->set_level(srslte::LOG_LEVEL_DEBUG); - log2->set_level(srslte::LOG_LEVEL_DEBUG); - log1->set_hex_limit(-1); - log2->set_hex_limit(-1); + logger1.set_level(srslog::basic_levels::debug); + logger1.set_hex_dump_max_size(-1); + logger2.set_level(srslog::basic_levels::debug); + logger2.set_hex_dump_max_size(-1); // configure RLC entities rlc_config_t cnfg = rlc_config_t::default_rlc_um_config(10); @@ -58,7 +58,8 @@ public: tester.set_expected_sdu_len(1); } - srslte::log_ref log1, log2; + srslog::basic_logger& logger1; + srslog::basic_logger& logger2; srslte::timer_handler timers; rlc_um_tester tester; rlc_um_lte rlc1, rlc2; @@ -426,6 +427,8 @@ int pdu_pack_no_space_test() int main(int argc, char** argv) { + srslog::init(); + if (meas_obj_test()) { return -1; }