diff --git a/lib/include/srsran/rlc/rlc_am_base.h b/lib/include/srsran/rlc/rlc_am_base.h index 128eb5abb..27f1f3555 100644 --- a/lib/include/srsran/rlc/rlc_am_base.h +++ b/lib/include/srsran/rlc/rlc_am_base.h @@ -125,7 +125,7 @@ public: class rlc_am_base_tx { public: - explicit rlc_am_base_tx(srslog::basic_logger* logger_) : logger(logger_) {} + explicit rlc_am_base_tx(srslog::basic_logger& logger_) : logger(logger_) {} virtual ~rlc_am_base_tx() = default; virtual bool configure(const rlc_config_t& cfg_) = 0; @@ -146,7 +146,7 @@ public: bool tx_enabled = false; byte_buffer_pool* pool = nullptr; - srslog::basic_logger* logger; + srslog::basic_logger& logger; std::string rb_name; bsr_callback_t bsr_callback; @@ -166,7 +166,7 @@ public: class rlc_am_base_rx { public: - explicit rlc_am_base_rx(rlc_am* parent_, srslog::basic_logger* logger_) : parent(parent_), logger(logger_) {} + explicit rlc_am_base_rx(rlc_am* parent_, srslog::basic_logger& logger_) : parent(parent_), logger(logger_) {} virtual ~rlc_am_base_rx() = default; virtual bool configure(const rlc_config_t& cfg_) = 0; @@ -178,7 +178,7 @@ public: void write_pdu(uint8_t* payload, uint32_t nof_bytes); - srslog::basic_logger* logger = nullptr; + srslog::basic_logger& logger; byte_buffer_pool* pool = nullptr; rlc_am* parent = nullptr; std::string rb_name; diff --git a/lib/include/srsran/rlc/rlc_common.h b/lib/include/srsran/rlc/rlc_common.h index a67b29609..f7992a472 100644 --- a/lib/include/srsran/rlc/rlc_common.h +++ b/lib/include/srsran/rlc/rlc_common.h @@ -39,6 +39,11 @@ namespace srsran { #define RlcWarning(fmt, ...) logger.warning("%s: " fmt, rb_name, ##__VA_ARGS__) #define RlcError(fmt, ...) logger.error("%s: " fmt, rb_name, ##__VA_ARGS__) +#define RlcHexDebug(msg, bytes, fmt, ...) logger.debug(msg, bytes, "%s: " fmt, rb_name, ##__VA_ARGS__) +#define RlcHexInfo(msg, bytes, fmt, ...) logger.info(msg, bytes, "%s: " fmt, rb_name, ##__VA_ARGS__) +#define RlcHexWarning(msg, bytes, fmt, ...) logger.warning(msg, bytes, "%s: " fmt, rb_name, ##__VA_ARGS__) +#define RlcHexError(msg, bytes, fmt, ...) logger.error(msg, bytes, "%s: " fmt, rb_name, ##__VA_ARGS__) + typedef enum { RLC_FI_FIELD_START_AND_END_ALIGNED = 0, RLC_FI_FIELD_NOT_END_ALIGNED, diff --git a/lib/src/rlc/rlc_am_base.cc b/lib/src/rlc/rlc_am_base.cc index 9764994de..72f553283 100644 --- a/lib/src/rlc/rlc_am_base.cc +++ b/lib/src/rlc/rlc_am_base.cc @@ -209,7 +209,7 @@ int rlc_am::rlc_am_base_tx::write_sdu(unique_byte_buffer_t sdu) } if (sdu.get() == nullptr) { - logger->warning("NULL SDU pointer in write_sdu()"); + RlcWarning("NULL SDU pointer in write_sdu()"); return SRSRAN_ERROR; } @@ -221,15 +221,15 @@ int rlc_am::rlc_am_base_tx::write_sdu(unique_byte_buffer_t sdu) uint32_t nof_bytes = sdu->N_bytes; srsran::error_type ret = tx_sdu_queue.try_write(std::move(sdu)); if (ret) { - logger->info(msg_ptr, nof_bytes, "%s Tx SDU (%d B, tx_sdu_queue_len=%d)", rb_name, nof_bytes, tx_sdu_queue.size()); + RlcHexInfo(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 - 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()); + RlcHexWarning(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()); return SRSRAN_ERROR; } @@ -248,7 +248,7 @@ void rlc_am::rlc_am_base_tx::set_bsr_callback(bsr_callback_t callback) *******************************************************/ void rlc_am::rlc_am_base_rx::write_pdu(uint8_t* payload, const uint32_t nof_bytes) { - logger->info("Rx PDU -- N bytes %d", nof_bytes); + RlcInfo("Rx PDU -- N bytes %d", nof_bytes); if (nof_bytes < 1) { return; } diff --git a/lib/src/rlc/rlc_am_lte.cc b/lib/src/rlc/rlc_am_lte.cc index b9bf657e1..9b527f88f 100644 --- a/lib/src/rlc/rlc_am_lte.cc +++ b/lib/src/rlc/rlc_am_lte.cc @@ -37,7 +37,7 @@ rlc_am_lte_tx::rlc_am_lte_tx(rlc_am* parent_) : pool(byte_buffer_pool::get_instance()), poll_retx_timer(parent_->timers->get_unique_timer()), status_prohibit_timer(parent_->timers->get_unique_timer()), - rlc_am_base_tx(&parent_->logger) + rlc_am_base_tx(parent_->logger) { rx = dynamic_cast(parent->rx_base.get()); } @@ -46,9 +46,9 @@ bool rlc_am_lte_tx::configure(const rlc_config_t& cfg_) { std::lock_guard lock(mutex); if (cfg_.tx_queue_length > MAX_SDUS_PER_RLC_PDU) { - logger->error("Configuring Tx queue length of %d PDUs too big. Maximum value is %d.", - cfg_.tx_queue_length, - MAX_SDUS_PER_RLC_PDU); + RlcError("Configuring Tx queue length of %d PDUs too big. Maximum value is %d.", + cfg_.tx_queue_length, + MAX_SDUS_PER_RLC_PDU); return false; } @@ -57,7 +57,7 @@ bool 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()) { - logger->error("Configuring RLC AM TX: timers not configured"); + RlcError("Configuring RLC AM TX: timers not configured"); return false; } @@ -171,7 +171,7 @@ bool rlc_am_lte_tx::has_data() void rlc_am_lte_tx::check_sn_reached_max_retx(uint32_t sn) { if (tx_window[sn].retx_count == cfg.max_retx_thresh) { - logger->warning("%s Signaling max number of reTx=%d for SN=%d", RB_NAME, tx_window[sn].retx_count, sn); + RlcWarning("Signaling max number of reTx=%d for SN=%d", tx_window[sn].retx_count, sn); parent->rrc->max_retx_attempted(); srsran::pdcp_sn_vector_t pdcp_sns; for (const rlc_am_pdu_segment& segment : tx_window[sn]) { @@ -207,36 +207,34 @@ void rlc_am_lte_tx::get_buffer_state_nolock(uint32_t& n_bytes_newtx, uint32_t& n return; } - logger->debug("%s Buffer state - do_status=%s, status_prohibit_running=%s (%d/%d)", - parent->rb_name, - do_status() ? "yes" : "no", - status_prohibit_timer.is_running() ? "yes" : "no", - status_prohibit_timer.time_elapsed(), - status_prohibit_timer.duration()); + RlcDebug("Buffer state - do_status=%s, status_prohibit_running=%s (%d/%d)", + 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_prio += rx->get_status_pdu_length(); - logger->debug("%s Buffer state - total status report: %d bytes", RB_NAME, n_bytes_prio); + RlcDebug("Buffer state - total status report: %d bytes", n_bytes_prio); } // Bytes needed for retx if (not retx_queue.empty()) { rlc_amd_retx_t& retx = retx_queue.front(); - 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); + RlcDebug("%s Buffer state - retx - SN=%d, Segment: %s, %d:%d", + retx.sn, + retx.is_segment ? "true" : "false", + retx.so_start, + retx.so_end); if (tx_window.has_sn(retx.sn)) { int req_bytes = required_buffer_size(retx); if (req_bytes < 0) { - logger->error("In get_buffer_state(): Removing retx.sn=%d from queue", retx.sn); + RlcError("In get_buffer_state(): Removing retx.sn=%d from queue", retx.sn); retx_queue.pop(); } else { n_bytes_prio += req_bytes; - logger->debug("Buffer state - retx: %d bytes", n_bytes_prio); + RlcDebug("Buffer state - retx: %d bytes", n_bytes_prio); } } } @@ -259,11 +257,11 @@ void rlc_am_lte_tx::get_buffer_state_nolock(uint32_t& n_bytes_newtx, uint32_t& n // Room needed for fixed header of data PDUs if (n_bytes_newtx > 0 && n_sdus > 0) { n_bytes_newtx += 2; // Two bytes for fixed header with SN length = 10 - logger->debug("%s Total buffer state - %d SDUs (%d B)", RB_NAME, n_sdus, n_bytes_newtx); + RlcDebug("%s Total buffer state - %d SDUs (%d B)", RB_NAME, n_sdus, n_bytes_newtx); } if (bsr_callback) { - logger->debug("%s Calling BSR callback - %d new_tx, %d prio bytes", RB_NAME, n_bytes_newtx, n_bytes_prio); + RlcDebug("%s Calling BSR callback - %d new_tx, %d prio bytes", RB_NAME, n_bytes_newtx, n_bytes_prio); bsr_callback(parent->lcid, n_bytes_newtx, n_bytes_prio); } } @@ -283,7 +281,7 @@ void rlc_am_lte_tx::discard_sdu(uint32_t discard_sn) }); // Discard fails when the PDCP PDU is already in Tx window. - logger->info("%s PDU with PDCP_SN=%d", discarded ? "Discarding" : "Couldn't discard", discard_sn); + RlcInfo("%s PDU with PDCP_SN=%d", discarded ? "Discarding" : "Couldn't discard", discard_sn); } bool rlc_am_lte_tx::sdu_queue_is_full() @@ -299,11 +297,11 @@ uint32_t rlc_am_lte_tx::read_pdu(uint8_t* payload, uint32_t nof_bytes) return 0; } - logger->debug("MAC opportunity - %d bytes", nof_bytes); - logger->debug("tx_window size - %zu PDUs", tx_window.size()); + RlcDebug("MAC opportunity - %d bytes", nof_bytes); + RlcDebug("tx_window size - %zu PDUs", tx_window.size()); if (not tx_enabled) { - logger->debug("RLC entity not active. Not generating PDU."); + RlcDebug("RLC entity not active. Not generating PDU."); return 0; } @@ -333,7 +331,7 @@ void rlc_am_lte_tx::timer_expired(uint32_t timeout_id) { std::unique_lock lock(mutex); if (poll_retx_timer.is_valid() && poll_retx_timer.id() == timeout_id) { - logger->debug("%s Poll reTx timer expired after %dms", RB_NAME, poll_retx_timer.duration()); + RlcDebug("Poll retx timer expired after %dms", poll_retx_timer.duration()); // Section 5.2.2.3 in TS 36.322, schedule PDU for retransmission if // (a) both tx and retx buffer are empty (excluding tx'ed PDU waiting for ack), or // (b) no new data PDU can be transmitted (tx window is full) @@ -341,7 +339,7 @@ void rlc_am_lte_tx::timer_expired(uint32_t timeout_id) retransmit_pdu(vt_a); // TODO: TS says to send vt_s - 1 here } } else if (status_prohibit_timer.is_valid() && status_prohibit_timer.id() == timeout_id) { - logger->debug("%s Status prohibit timer expired after %dms", RB_NAME, status_prohibit_timer.duration()); + RlcDebug("Status prohibit timer expired after %dms", status_prohibit_timer.duration()); } if (bsr_callback) { @@ -353,12 +351,12 @@ void rlc_am_lte_tx::timer_expired(uint32_t timeout_id) void rlc_am_lte_tx::retransmit_pdu(uint32_t sn) { if (tx_window.empty()) { - logger->warning("%s No PDU to retransmit", RB_NAME); + RlcWarning("%s No PDU to retransmit"); return; } if (not tx_window.has_sn(sn)) { - logger->warning("%s Can't retransmit unexisting SN=%d", RB_NAME, sn); + RlcWarning("%s Can't retransmit unexisting SN=%d", RB_NAME, sn); return; } @@ -369,7 +367,7 @@ void rlc_am_lte_tx::retransmit_pdu(uint32_t sn) pdu.retx_count++; check_sn_reached_max_retx(sn); - logger->info("%s Schedule SN=%d for reTx", RB_NAME, pdu.rlc_sn); + RlcInfo("%s Schedule SN=%d for retx", RB_NAME, pdu.rlc_sn); rlc_amd_retx_t& retx = retx_queue.push(); retx.is_segment = false; @@ -393,28 +391,28 @@ void rlc_am_lte_tx::retransmit_pdu(uint32_t sn) bool rlc_am_lte_tx::poll_required() { if (cfg.poll_pdu > 0 && pdu_without_poll > static_cast(cfg.poll_pdu)) { - logger->debug("Poll required. Cause: PDU_WITHOUT_POLL > pollPdu."); + RlcDebug("Poll required. Cause: PDU_WITHOUT_POLL > pollPdu."); return true; } if (cfg.poll_byte > 0 && byte_without_poll > static_cast(cfg.poll_byte)) { - logger->debug("Poll required. Cause: BYTE_WITHOUT_POLL > pollByte."); + RlcDebug("Poll required. Cause: BYTE_WITHOUT_POLL > pollByte."); return true; } if (poll_retx_timer.is_valid() && poll_retx_timer.is_expired()) { // re-arming of timer is handled by caller - logger->debug("Poll required. Cause: t-PollRetransmission expired."); + RlcDebug("Poll required. Cause: t-PollRetransmission expired."); return true; } if (tx_window.size() >= RLC_AM_WINDOW_SIZE) { - logger->debug("Poll required. Cause: TX window full."); + RlcDebug("Poll required. Cause: TX window full."); return true; } if (tx_sdu_queue.size() == 0 && retx_queue.empty()) { - logger->debug("Poll required. Cause: Empty TX and ReTX queues."); + RlcDebug("Poll required. Cause: Empty TX and ReTX queues."); return true; } @@ -432,13 +430,13 @@ bool rlc_am_lte_tx::poll_required() int rlc_am_lte_tx::build_status_pdu(uint8_t* payload, uint32_t nof_bytes) { - logger->debug("%s Generating status PDU. Nof bytes %d", RB_NAME, nof_bytes); + RlcDebug("%s Generating status PDU. Nof bytes %d", RB_NAME, nof_bytes); int pdu_len = rx->get_status_pdu(&tx_status, nof_bytes); if (pdu_len == SRSRAN_ERROR) { - logger->debug("%s Deferred Status PDU. Cause: Failed to acquire Rx lock", RB_NAME); + RlcDebug("%s Deferred Status PDU. Cause: Failed to acquire Rx lock", RB_NAME); pdu_len = 0; } else if (pdu_len > 0 && nof_bytes >= static_cast(pdu_len)) { - log_rlc_am_status_pdu_to_string(logger->info, "%s Tx status PDU - %s", &tx_status, RB_NAME); + log_rlc_am_status_pdu_to_string(logger.info, "%s Tx status PDU - %s", &tx_status, RB_NAME); if (cfg.t_status_prohibit > 0 && status_prohibit_timer.is_valid()) { // re-arm timer status_prohibit_timer.run(); @@ -446,7 +444,7 @@ int rlc_am_lte_tx::build_status_pdu(uint8_t* payload, uint32_t nof_bytes) debug_state(); pdu_len = rlc_am_write_status_pdu(&tx_status, payload); } else { - logger->info("%s Cannot tx status PDU - %d bytes available, %d bytes required", RB_NAME, nof_bytes, pdu_len); + RlcInfo("Cannot tx status PDU - %d bytes available, %d bytes required", nof_bytes, pdu_len); pdu_len = 0; } @@ -457,7 +455,7 @@ int rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_bytes) { // Check there is at least 1 element before calling front() if (retx_queue.empty()) { - logger->error("In build_retx_pdu(): retx_queue is empty"); + RlcError("In build_retx_pdu(): retx_queue is empty"); return -1; } @@ -469,7 +467,7 @@ int rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_bytes) if (!retx_queue.empty()) { retx = retx_queue.front(); } else { - logger->info("%s SN=%d not in Tx window. Ignoring retx.", RB_NAME, retx.sn); + RlcInfo("%s SN=%d not in Tx window. Ignoring retx.", RB_NAME, retx.sn); if (tx_window.has_sn(vt_a)) { // schedule next SN for retx retransmit_pdu(vt_a); @@ -484,13 +482,13 @@ int rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_bytes) // Is resegmentation needed? int req_size = required_buffer_size(retx); if (req_size < 0) { - logger->error("In build_retx_pdu(): Removing retx.sn=%d from queue", retx.sn); + RlcError("In build_retx_pdu(): Removing retx.sn=%d from queue", retx.sn); retx_queue.pop(); return -1; } if (retx.is_segment || req_size > static_cast(nof_bytes)) { - logger->debug("%s build_retx_pdu - resegmentation required", RB_NAME); + RlcDebug("%s build_retx_pdu - resegmentation required", RB_NAME); return build_segment(payload, nof_bytes, retx); } @@ -501,8 +499,8 @@ int rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_bytes) // Set poll bit pdu_without_poll++; byte_without_poll += (tx_window[retx.sn].buf->N_bytes + rlc_am_packed_length(&new_header)); - logger->info("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll); - logger->info("%s byte_without_poll: %d", RB_NAME, byte_without_poll); + RlcInfo("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll); + RlcInfo("%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 @@ -510,7 +508,7 @@ int rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_bytes) byte_without_poll = 0; if (poll_retx_timer.is_valid()) { // re-arm timer (will be stopped when status PDU is received) - logger->debug("%s re-arming retx timer", RB_NAME); + RlcDebug("%s re-arming retx timer", RB_NAME); poll_retx_timer.run(); } } @@ -521,15 +519,14 @@ int rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_bytes) retx_queue.pop(); - 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); - log_rlc_amd_pdu_header_to_string(logger->debug, new_header); + RlcHexInfo(payload, + tx_window[retx.sn].buf->N_bytes, + "Tx PDU SN=%d (%d B) (attempt %d/%d)", + retx.sn, + tx_window[retx.sn].buf->N_bytes, + tx_window[retx.sn].retx_count + 1, + cfg.max_retx_thresh); + log_rlc_amd_pdu_header_to_string(logger.debug, new_header); debug_state(); return (ptr - payload) + tx_window[retx.sn].buf->N_bytes; @@ -538,7 +535,7 @@ int rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_bytes) int 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) { - logger->error("In build_segment: retx.sn=%d has null buffer", retx.sn); + RlcError("In build_segment: retx.sn=%d has null buffer", retx.sn); return 0; } if (!retx.is_segment) { @@ -552,8 +549,8 @@ int rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_bytes, rlc_amd_r pdu_without_poll++; byte_without_poll += (tx_window[retx.sn].buf->N_bytes + rlc_am_packed_length(&new_header)); - logger->info("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll); - logger->info("%s byte_without_poll: %d", RB_NAME, byte_without_poll); + RlcInfo("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll); + RlcInfo("%s byte_without_poll: %d", RB_NAME, byte_without_poll); new_header.dc = RLC_DC_FIELD_DATA_PDU; new_header.rf = 1; @@ -574,10 +571,10 @@ int rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_bytes, rlc_amd_r } if (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); + RlcInfo("%s Cannot build a PDU segment - %d bytes available, %d bytes required for header", + RB_NAME, + nof_bytes, + head_len); return 0; } @@ -670,7 +667,7 @@ int rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_bytes, rlc_amd_r // Check POLL requeriments for segment if (poll_required()) { - logger->debug("%s setting poll bit to request status", RB_NAME); + RlcDebug("setting poll bit to request status"); new_header.p = 1; // vt_s won't change for reTx, so don't update poll_sn pdu_without_poll = 0; @@ -690,24 +687,22 @@ int rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_bytes, rlc_amd_r debug_state(); int pdu_len = (ptr - payload) + len; if (pdu_len > static_cast(nof_bytes)) { - logger->error("%s Retx PDU segment length error. Available: %d, Used: %d", RB_NAME, nof_bytes, pdu_len); + RlcError("Retx PDU segment length error. Available: %d, Used: %d", nof_bytes, pdu_len); int header_len = (ptr - payload); - logger->debug("%s Retx PDU segment length error. Actual header len: %d, Payload len: %d, N_li: %d", - RB_NAME, - header_len, - len, - new_header.N_li); + RlcDebug("Retx PDU segment length error. Actual header len: %d, Payload len: %d, N_li: %d", + header_len, + len, + new_header.N_li); } - 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); + RlcHexInfo(payload, + pdu_len, + "retx PDU segment SN=%d [so=%d] (%d B) (attempt %d/%d)", + retx.sn, + retx.so_start, + pdu_len, + tx_window[retx.sn].retx_count + 1, + cfg.max_retx_thresh); return pdu_len; } @@ -715,21 +710,21 @@ int rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_bytes, rlc_amd_r int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) { if (tx_sdu == NULL && tx_sdu_queue.is_empty()) { - logger->info("No data available to be sent"); + RlcInfo("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) { - logger->info("Tx window full."); + RlcInfo("Tx window full."); return 0; } if (nof_bytes < RLC_AM_MIN_DATA_PDU_SIZE) { - logger->info("%s Cannot build data PDU - %d bytes available but at least %d bytes are required ", - RB_NAME, - nof_bytes, - RLC_AM_MIN_DATA_PDU_SIZE); + RlcInfo("%s Cannot build data PDU - %d bytes available but at least %d bytes are required ", + RB_NAME, + nof_bytes, + RLC_AM_MIN_DATA_PDU_SIZE); return 0; } @@ -746,7 +741,7 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) } exit(-1); #else - logger->error("Fatal Error: Couldn't allocate PDU in build_data_pdu()."); + RlcError("Fatal Error: Couldn't allocate PDU in build_data_pdu()."); return 0; #endif } @@ -756,7 +751,7 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) header.sn = vt_s; if (not segment_pool.has_segments()) { - logger->info("Can't build a PDU - No segments available"); + RlcInfo("Can't build a PDU - No segments available"); return 0; } @@ -770,7 +765,7 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) uint32_t pdu_space = SRSRAN_MIN(nof_bytes, pdu->get_tailroom()); uint8_t* pdu_ptr = pdu->msg; - logger->debug("%s Building PDU - pdu_space: %d, head_len: %d ", RB_NAME, pdu_space, head_len); + RlcDebug("%s Building PDU - pdu_space: %d, head_len: %d ", pdu_space, head_len); // Check for SDU segment if (tx_sdu != nullptr) { @@ -789,11 +784,11 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) } } else { // PDCP SNs for the RLC SDU has been removed from the queue - logger->warning("Couldn't find PDCP_SN=%d in SDU info queue (segment)", tx_sdu->md.pdcp_sn); + RlcWarning("Couldn't find PDCP_SN=%d in SDU info queue (segment)", tx_sdu->md.pdcp_sn); } if (tx_sdu->N_bytes == 0) { - logger->debug("%s Complete SDU scheduled for tx.", RB_NAME); + RlcDebug("%s Complete SDU scheduled for tx.", RB_NAME); tx_sdu.reset(); } if (pdu_space > to_move) { @@ -803,7 +798,7 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) } header.fi |= RLC_FI_FIELD_NOT_START_ALIGNED; // First byte does not correspond to first byte of SDU - logger->debug( + RlcDebug( "%s Building PDU - added SDU segment from previous PDU (len:%d) - pdu_space: %d, head_len: %d header_sn=%d", RB_NAME, to_move, @@ -815,7 +810,7 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) // Pull SDUs from queue while (pdu_space > head_len && tx_sdu_queue.get_n_sdus() > 0 && header.N_li < MAX_SDUS_PER_PDU) { if (not segment_pool.has_segments()) { - logger->info("Can't build a PDU segment - No segment resources available"); + RlcInfo("Can't build a PDU segment - No segment resources available"); if (pdu_ptr != pdu->msg) { break; // continue with the segments created up to this point } @@ -846,11 +841,11 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) // store sdu info if (undelivered_sdu_info_queue.has_pdcp_sn(tx_sdu->md.pdcp_sn)) { - logger->warning("PDCP_SN=%d already marked as undelivered", tx_sdu->md.pdcp_sn); + RlcWarning("PDCP_SN=%d already marked as undelivered", tx_sdu->md.pdcp_sn); } else { - logger->debug("marking pdcp_sn=%d as undelivered (queue_len=%ld)", - tx_sdu->md.pdcp_sn, - undelivered_sdu_info_queue.nof_sdus()); + RlcDebug("marking pdcp_sn=%d as undelivered (queue_len=%ld)", + tx_sdu->md.pdcp_sn, + undelivered_sdu_info_queue.nof_sdus()); undelivered_sdu_info_queue.add_pdcp_sdu(tx_sdu->md.pdcp_sn); } pdcp_pdu_info_lte& pdcp_pdu = undelivered_sdu_info_queue[tx_sdu->md.pdcp_sn]; @@ -868,7 +863,7 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) } if (tx_sdu->N_bytes == 0) { - logger->debug("%s Complete SDU scheduled for tx. PDCP SN=%d", RB_NAME, tx_sdu->md.pdcp_sn); + RlcDebug("%s Complete SDU scheduled for tx. PDCP SN=%d", RB_NAME, tx_sdu->md.pdcp_sn); tx_sdu.reset(); } if (pdu_space > to_move) { @@ -877,16 +872,16 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) pdu_space = 0; } - logger->debug("%s Building PDU - added SDU segment (len:%d) - pdu_space: %d, head_len: %d ", - RB_NAME, - to_move, - pdu_space, - head_len); + RlcDebug("%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) { - logger->error("Generated empty RLC PDU."); + RlcError("Generated empty RLC PDU."); } if (tx_sdu != NULL) { @@ -896,10 +891,10 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) // Set Poll bit pdu_without_poll++; byte_without_poll += (pdu->N_bytes + head_len); - logger->debug("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll); - logger->debug("%s byte_without_poll: %d", RB_NAME, byte_without_poll); + RlcDebug("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll); + RlcDebug("%s byte_without_poll: %d", RB_NAME, byte_without_poll); if (poll_required()) { - logger->debug("%s setting poll bit to request status", RB_NAME); + RlcDebug("%s setting poll bit to request status", RB_NAME); header.p = 1; poll_sn = vt_s; pdu_without_poll = 0; @@ -921,8 +916,8 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) 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; - logger->info(payload, total_len, "%s Tx PDU SN=%d (%d B)", RB_NAME, header.sn, total_len); - log_rlc_amd_pdu_header_to_string(logger->debug, header); + RlcHexInfo(payload, total_len, "Tx PDU SN=%d (%d B)", header.sn, total_len); + log_rlc_amd_pdu_header_to_string(logger.debug, header); debug_state(); return total_len; @@ -942,27 +937,27 @@ void rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_bytes) { std::lock_guard lock(mutex); - logger->debug(payload, nof_bytes, "%s Rx control PDU", RB_NAME); + RlcHexDebug(payload, nof_bytes, "Rx control PDU"); rlc_am_read_status_pdu(payload, nof_bytes, &status); - log_rlc_am_status_pdu_to_string(logger->info, "%s Rx Status PDU: %s", &status, RB_NAME); + log_rlc_am_status_pdu_to_string(logger.info, "%s Rx Status PDU: %s", &status, RB_NAME); // make sure ACK_SN is within our Tx window if (((MOD + status.ack_sn - vt_a) % MOD > RLC_AM_WINDOW_SIZE) || ((MOD + vt_s - status.ack_sn) % MOD > RLC_AM_WINDOW_SIZE)) { - logger->warning("%s Received invalid status PDU (ack_sn=%d, vt_a=%d, vt_s=%d). Dropping PDU.", - RB_NAME, - status.ack_sn, - vt_a, - vt_s); + RlcWarning("%s Received invalid status PDU (ack_sn=%d, vt_a=%d, vt_s=%d). Dropping PDU.", + RB_NAME, + status.ack_sn, + vt_a, + vt_s); return; } // 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))) { - logger->debug("%s Stopping pollRetx timer", RB_NAME); + RlcDebug("%s Stopping pollRetx timer", RB_NAME); poll_retx_timer.stop(); } @@ -1003,8 +998,7 @@ void rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_bytes) // sanity check if (status.nacks[j].so_start >= pdu.buf->N_bytes) { // print error but try to send original PDU again - logger->info( - "SO_start is larger than original PDU (%d >= %d)", status.nacks[j].so_start, pdu.buf->N_bytes); + RlcInfo("SO_start is larger than original PDU (%d >= %d)", status.nacks[j].so_start, pdu.buf->N_bytes); status.nacks[j].so_start = 0; } @@ -1019,19 +1013,18 @@ void rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_bytes) retx.is_segment = true; retx.so_start = status.nacks[j].so_start; } else { - 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, - pdu.buf->N_bytes); + RlcWarning("invalid segment NACK received for SN %d. so_start: %d, so_end: %d, N_bytes: %d", + i, + status.nacks[j].so_start, + status.nacks[j].so_end, + pdu.buf->N_bytes); } } } else { - logger->info("%s NACKed SN=%d already considered for retransmission", RB_NAME, i); + RlcInfo("NACKed SN=%d already considered for retransmission", i); } } else { - logger->error("%s NACKed SN=%d already removed from Tx window", RB_NAME, i); + RlcError("NACKed SN=%d already removed from Tx window", i); } } } @@ -1041,7 +1034,7 @@ void rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_bytes) std::lock_guard lock(mutex); if (tx_window.has_sn(i)) { update_notification_ack_info(i); - logger->debug("Tx PDU SN=%zd being removed from tx window", i); + RlcDebug("Tx PDU SN=%zd being removed from tx window", i); tx_window.remove_pdu(i); } // Advance window if possible @@ -1057,7 +1050,7 @@ void rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_bytes) // Make sure vt_a points to valid SN std::lock_guard lock(mutex); if (not tx_window.empty() && not tx_window.has_sn(vt_a)) { - logger->error("%s vt_a=%d points to invalid position in Tx window.", RB_NAME, vt_a); + RlcError("vt_a=%d points to invalid position in Tx window.", vt_a); parent->rrc->protocol_failure(); } } @@ -1078,10 +1071,10 @@ void rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_bytes) */ void rlc_am_lte_tx::update_notification_ack_info(uint32_t rlc_sn) { - logger->debug("Updating ACK info: RLC SN=%d, number of notified SDU=%ld, number of undelivered SDUs=%ld", - rlc_sn, - notify_info_vec.size(), - undelivered_sdu_info_queue.nof_sdus()); + RlcDebug("Updating ACK info: RLC SN=%d, number of notified SDU=%ld, number of undelivered SDUs=%ld", + rlc_sn, + notify_info_vec.size(), + undelivered_sdu_info_queue.nof_sdus()); // Iterate over all undelivered SDUs if (not tx_window.has_sn(rlc_sn)) { return; @@ -1091,7 +1084,7 @@ void rlc_am_lte_tx::update_notification_ack_info(uint32_t rlc_sn) for (rlc_am_pdu_segment& acked_segment : acked_pdu) { uint32_t pdcp_sn = acked_segment.pdcp_sn(); if (pdcp_sn == rlc_am_pdu_segment::invalid_pdcp_sn) { - logger->debug("ACKed segment in RLC_SN=%d already discarded in PDCP. No need to notify the PDCP.", rlc_sn); + RlcDebug("ACKed segment in RLC_SN=%d already discarded in PDCP. No need to notify the PDCP.", rlc_sn); continue; } pdcp_pdu_info_lte& info = undelivered_sdu_info_queue[pdcp_sn]; @@ -1105,9 +1098,9 @@ void rlc_am_lte_tx::update_notification_ack_info(uint32_t rlc_sn) if (not notify_info_vec.full()) { notify_info_vec.push_back(pdcp_sn); } else { - logger->warning("Can't notify delivery of PDCP_SN=%d.", pdcp_sn); + RlcWarning("Can't notify delivery of PDCP_SN=%d.", pdcp_sn); } - logger->debug("Erasing SDU info: PDCP_SN=%d", pdcp_sn); + RlcDebug("Erasing SDU info: PDCP_SN=%d", pdcp_sn); undelivered_sdu_info_queue.clear_pdcp_sdu(pdcp_sn); } } @@ -1115,7 +1108,7 @@ void rlc_am_lte_tx::update_notification_ack_info(uint32_t rlc_sn) void rlc_am_lte_tx::debug_state() { - 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); + RlcDebug("%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_tx::required_buffer_size(const rlc_amd_retx_t& retx) @@ -1125,11 +1118,11 @@ int rlc_am_lte_tx::required_buffer_size(const 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 { - logger->warning("retx.sn=%d has null ptr in required_buffer_size()", retx.sn); + RlcWarning("retx.sn=%d has null ptr in required_buffer_size()", retx.sn); return -1; } } else { - logger->warning("retx.sn=%d does not exist in required_buffer_size()", retx.sn); + RlcWarning("retx.sn=%d does not exist in required_buffer_size()", retx.sn); return -1; } } @@ -1198,7 +1191,7 @@ rlc_am_lte_rx::rlc_am_lte_rx(rlc_am* parent_) : parent(parent_), pool(byte_buffer_pool::get_instance()), reordering_timer(parent_->timers->get_unique_timer()), - rlc_am_base_rx(parent_, &parent_->logger) + rlc_am_base_rx(parent_, parent_->logger) {} bool rlc_am_lte_rx::configure(const rlc_config_t& cfg_) @@ -1208,7 +1201,7 @@ bool rlc_am_lte_rx::configure(const rlc_config_t& cfg_) // check timers if (not reordering_timer.is_valid()) { - logger->error("Configuring RLC AM TX: timers not configured"); + RlcError("Configuring RLC AM TX: timers not configured"); return false; } @@ -1264,7 +1257,7 @@ void rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_bytes) uint32_t payload_len = nof_bytes; rlc_am_read_data_pdu_header(&payload, &payload_len, &header); if (payload_len > nof_bytes) { - logger->info("Dropping corrupted PDU (%d B). Remaining length after header %d B.", nof_bytes, payload_len); + RlcInfo("Dropping corrupted PDU (%d B). Remaining length after header %d B.", nof_bytes, payload_len); return; } if (header.rf != 0) { @@ -1284,8 +1277,8 @@ void rlc_am_lte_rx::handle_data_pdu_full(uint8_t* payload, uint32_t nof_bytes, r { std::map::iterator it; - logger->info(payload, nof_bytes, "%s Rx data PDU SN=%d (%d B)", RB_NAME, header.sn, nof_bytes); - log_rlc_amd_pdu_header_to_string(logger->debug, header); + RlcHexInfo(payload, nof_bytes, "Rx data PDU SN=%d (%d B)", header.sn, nof_bytes); + log_rlc_amd_pdu_header_to_string(logger.debug, header); // sanity check for segments not exceeding PDU length if (header.N_li > 0) { @@ -1293,7 +1286,7 @@ void rlc_am_lte_rx::handle_data_pdu_full(uint8_t* payload, uint32_t nof_bytes, r for (uint32_t i = 0; i < header.N_li; i++) { segments_len += header.li[i]; if (segments_len > nof_bytes) { - logger->info("Dropping corrupted PDU (segments_len=%d > pdu_len=%d)", segments_len, nof_bytes); + RlcInfo("Dropping corrupted PDU (segments_len=%d > pdu_len=%d)", segments_len, nof_bytes); return; } } @@ -1301,19 +1294,19 @@ void rlc_am_lte_rx::handle_data_pdu_full(uint8_t* payload, uint32_t nof_bytes, r if (!inside_rx_window(header.sn)) { if (header.p) { - logger->info("%s Status packet requested through polling bit", RB_NAME); + RlcInfo("Status packet requested through polling bit"); do_status = true; } - logger->info("%s SN=%d outside rx window [%d:%d] - discarding", RB_NAME, header.sn, vr_r, vr_mr); + RlcInfo("SN=%d outside rx window [%d:%d] - discarding", header.sn, vr_r, vr_mr); return; } if (rx_window.has_sn(header.sn)) { if (header.p) { - logger->info("%s Status packet requested through polling bit", RB_NAME); + RlcInfo("%s Status packet requested through polling bit"); do_status = true; } - logger->info("%s Discarding duplicate SN=%d", RB_NAME, header.sn); + RlcInfo("Discarding duplicate SN=%d", header.sn); return; } @@ -1325,7 +1318,7 @@ void rlc_am_lte_rx::handle_data_pdu_full(uint8_t* payload, uint32_t nof_bytes, r srsran::console("Fatal Error: Couldn't allocate PDU in handle_data_pdu().\n"); exit(-1); #else - logger->error("Fatal Error: Couldn't allocate PDU in handle_data_pdu()."); + RlcError("Fatal Error: Couldn't allocate PDU in handle_data_pdu()."); rx_window.remove_pdu(header.sn); return; #endif @@ -1334,11 +1327,7 @@ void rlc_am_lte_rx::handle_data_pdu_full(uint8_t* payload, uint32_t nof_bytes, r // check available space for payload if (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()); + RlcError("Discarding SN=%d of size %d B (available space %d B)", header.sn, nof_bytes, pdu.buf->get_tailroom()); return; } memcpy(pdu.buf->msg, payload, nof_bytes); @@ -1357,7 +1346,7 @@ void rlc_am_lte_rx::handle_data_pdu_full(uint8_t* payload, uint32_t nof_bytes, r // Check poll bit if (header.p) { - logger->info("%s Status packet requested through polling bit", RB_NAME); + RlcInfo("Status packet requested through polling bit"); poll_received = true; // 36.322 v10 Section 5.2.3 @@ -1374,21 +1363,21 @@ void rlc_am_lte_rx::handle_data_pdu_full(uint8_t* payload, uint32_t nof_bytes, r if (reordering_timer.is_valid()) { if (reordering_timer.is_running()) { if (vr_x == vr_r || (!inside_rx_window(vr_x) && vr_x != vr_mr)) { - logger->debug("Stopping reordering timer."); + RlcDebug("Stopping reordering timer."); reordering_timer.stop(); } else { - logger->debug("Leave reordering timer running."); + RlcDebug("Leave reordering timer running."); } debug_state(); } if (not reordering_timer.is_running()) { if (RX_MOD_BASE(vr_h) > RX_MOD_BASE(vr_r)) { - logger->debug("Starting reordering timer."); + RlcDebug("Starting reordering timer."); reordering_timer.run(); vr_x = vr_h; } else { - logger->debug("Leave reordering timer stopped."); + RlcDebug("Leave reordering timer stopped."); } debug_state(); } @@ -1401,23 +1390,22 @@ void rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* payload, uint32_t nof_bytes { std::map::iterator it; - 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); - log_rlc_amd_pdu_header_to_string(logger->debug, header); + RlcHexInfo(payload, + nof_bytes, + "Rx data PDU segment of SN=%d (%d B), SO=%d, N_li=%d", + header.sn, + nof_bytes, + header.so, + header.N_li); + log_rlc_amd_pdu_header_to_string(logger.debug, header); // Check inside rx window if (!inside_rx_window(header.sn)) { if (header.p) { - logger->info("%s Status packet requested through polling bit", RB_NAME); + logger.info("%s Status packet requested through polling bit"); do_status = true; } - logger->info("%s SN=%d outside rx window [%d:%d] - discarding", RB_NAME, header.sn, vr_r, vr_mr); + logger.info("SN=%d outside rx window [%d:%d] - discarding", header.sn, vr_r, vr_mr); return; } @@ -1428,13 +1416,13 @@ void rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* payload, uint32_t nof_bytes srsran::console("Fatal Error: Couldn't allocate PDU in handle_data_pdu_segment().\n"); exit(-1); #else - logger->error("Fatal Error: Couldn't allocate PDU in handle_data_pdu_segment()."); + logger.error("Fatal Error: Couldn't allocate PDU in handle_data_pdu_segment()."); return; #endif } if (segment.buf->get_tailroom() < nof_bytes) { - logger->info("Dropping corrupted segment SN=%d, not enough space to fit %d B", header.sn, nof_bytes); + logger.info("Dropping corrupted segment SN=%d, not enough space to fit %d B", header.sn, nof_bytes); return; } @@ -1446,7 +1434,7 @@ void rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* payload, uint32_t nof_bytes it = rx_segments.find(header.sn); if (rx_segments.end() != it) { if (header.p) { - logger->info("%s Status packet requested through polling bit", RB_NAME); + logger.info("Status packet requested through polling bit"); do_status = true; } @@ -1469,7 +1457,7 @@ void rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* payload, uint32_t nof_bytes // Check poll bit if (header.p) { - logger->info("%s Status packet requested through polling bit", RB_NAME); + RlcInfo("Status packet requested through polling bit"); poll_received = true; // 36.322 v10 Section 5.2.3 @@ -1495,7 +1483,7 @@ void rlc_am_lte_rx::reassemble_rx_sdus() srsran::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (1)\n"); exit(-1); #else - logger->error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (1)"); + RlcError("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (1)"); return; #endif } @@ -1507,13 +1495,13 @@ void 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]; - 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); + RlcHexDebug(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) { @@ -1523,7 +1511,7 @@ void 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 < SRSRAN_MAX_BUFFER_SIZE_BYTES) { if (rx_window[vr_r].buf->N_bytes < len) { - logger->error("Dropping corrupted SN=%d", vr_r); + RlcError("Dropping corrupted SN=%d", vr_r); rx_sdu.reset(); goto exit; } @@ -1537,7 +1525,7 @@ void rlc_am_lte_rx::reassemble_rx_sdus() rx_window[vr_r].buf->msg += len; rx_window[vr_r].buf->N_bytes -= len; - logger->info(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes); + RlcHexInfo(rx_sdu->msg, rx_sdu->N_bytes, "Rx SDU (%d B)", rx_sdu->N_bytes); sdu_rx_latency_ms.push(std::chrono::duration_cast( std::chrono::high_resolution_clock::now() - rx_sdu->get_timestamp()) .count()); @@ -1553,18 +1541,18 @@ void rlc_am_lte_rx::reassemble_rx_sdus() srsran::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (2)\n"); exit(-1); #else - logger->error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (2)"); + RlcError("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; - logger->error("Cannot read %d bytes from rx_window. vr_r=%d, msg-buffer=%d B", len, vr_r, buf_len); + RlcError("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 { - logger->error("Cannot fit RLC PDU in SDU buffer, dropping both."); + RlcError("Cannot fit RLC PDU in SDU buffer, dropping both."); rx_sdu.reset(); goto exit; } @@ -1572,7 +1560,7 @@ void rlc_am_lte_rx::reassemble_rx_sdus() // Handle last segment len = rx_window[vr_r].buf->N_bytes; - logger->debug(rx_window[vr_r].buf->msg, len, "Handling last segment of length %d B of SN=%d", len, vr_r); + RlcHexDebug(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) { @@ -1590,7 +1578,7 @@ void rlc_am_lte_rx::reassemble_rx_sdus() } if (rlc_am_end_aligned(rx_window[vr_r].header.fi)) { - logger->info(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes); + RlcHexInfo(rx_sdu->msg, rx_sdu->N_bytes, "Rx SDU (%d B)", rx_sdu->N_bytes); sdu_rx_latency_ms.push(std::chrono::duration_cast( std::chrono::high_resolution_clock::now() - rx_sdu->get_timestamp()) .count()); @@ -1606,7 +1594,7 @@ void rlc_am_lte_rx::reassemble_rx_sdus() srsran::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (3)\n"); exit(-1); #else - logger->error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (3)"); + RlcError("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (3)"); return; #endif } @@ -1614,19 +1602,19 @@ void rlc_am_lte_rx::reassemble_rx_sdus() exit: // Move the rx_window - logger->debug("Erasing SN=%d.", vr_r); + RlcDebug("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) { - logger->debug("Erasing segments of SN=%d", vr_r); + RlcDebug("Erasing segments of SN=%d", vr_r); std::list::iterator segit; for (segit = it->second.segments.begin(); segit != it->second.segments.end(); ++segit) { - 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); + RlcDebug(" 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(); } @@ -1668,7 +1656,7 @@ void rlc_am_lte_rx::timer_expired(uint32_t timeout_id) { std::lock_guard lock(mutex); if (reordering_timer.is_valid() and reordering_timer.id() == timeout_id) { - logger->debug("%s reordering timeout expiry - updating vr_ms (was %d)", RB_NAME, vr_ms); + RlcDebug("reordering timeout expiry - updating vr_ms (was %d)", vr_ms); // 36.322 v10 Section 5.1.3.2.4 vr_ms = vr_x; @@ -1714,23 +1702,22 @@ int rlc_am_lte_rx::get_status_pdu(rlc_status_pdu_t* status, const uint32_t max_p // make sure we don't exceed grant size if (rlc_am_packed_length(status) > max_pdu_size) { - logger->debug("Status PDU too big (%d > %d)", rlc_am_packed_length(status), max_pdu_size); + RlcDebug("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) { - logger->debug("Removing last NACK SN=%d", status->nacks[status->N_nack].nack_sn); + RlcDebug("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, vr_r) == false) { // No space to send any NACKs, play safe and just ack lower edge - logger->warning("Resetting ACK_SN and N_nack to initial state"); + RlcWarning("Resetting ACK_SN and N_nack to initial state"); status->ack_sn = vr_r; status->N_nack = 0; } } else { - 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); + RlcWarning("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); return 0; } break; @@ -1775,7 +1762,7 @@ void rlc_am_lte_rx::print_rx_segments() << " N_li: " << segit->header.N_li << std::endl; } } - logger->debug("%s", ss.str().c_str()); + RlcDebug("%s", ss.str().c_str()); } // NOTE: Preference would be to capture by value, and then move; but header is stack allocated @@ -1849,7 +1836,7 @@ bool rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* pdu, rlc_am 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); - logger->debug("Starting header reconstruction of %zd segments", pdu->segments.size()); + RlcDebug("Starting header reconstruction of %zd segments", pdu->segments.size()); // Reconstruct li fields uint16_t count = 0; @@ -1857,7 +1844,7 @@ bool rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* pdu, rlc_am uint16_t consumed_bytes = 0; // rolling sum of all allocated LIs during segment reconstruction for (it = pdu->segments.begin(); it != pdu->segments.end(); ++it) { - logger->debug(" Handling %d PDU segments", it->header.N_li); + RlcDebug(" Handling %d PDU segments", it->header.N_li); for (uint32_t i = 0; i < it->header.N_li; i++) { // variable marks total offset of each _processed_ LI of this segment uint32_t total_pdu_offset = it->header.so; @@ -1865,28 +1852,28 @@ bool rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* pdu, rlc_am total_pdu_offset += it->header.li[k]; } - logger->debug(" - (total_pdu_offset=%d, consumed_bytes=%d, header.li[i]=%d)", - total_pdu_offset, - consumed_bytes, - header.li[i]); + RlcDebug(" - (total_pdu_offset=%d, consumed_bytes=%d, header.li[i]=%d)", + total_pdu_offset, + consumed_bytes, + header.li[i]); if (total_pdu_offset > header.li[i] && total_pdu_offset > consumed_bytes) { header.li[header.N_li] = total_pdu_offset - consumed_bytes; consumed_bytes = total_pdu_offset; - 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); + RlcDebug(" - 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; } else { - logger->debug(" - Skipping segment in reTx PDU segment which is already included (%d B, SO=%d)", - it->header.li[i], - header.so); + RlcDebug(" - Skipping segment in reTx PDU segment which is already included (%d B, SO=%d)", + it->header.li[i], + header.so); } } @@ -1896,24 +1883,24 @@ bool rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* pdu, rlc_am for (uint32_t k = 0; k < header.N_li; ++k) { carryover -= header.li[k]; } - logger->debug("Incremented carryover (it->buf->N_bytes=%d, count=%d). New carryover=%d", - it->buf->N_bytes, - count, - carryover); + RlcDebug("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]); - 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]); + RlcDebug("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()) { - logger->debug("Header is end-aligned, overwrite header.li[%d]=%d", header.N_li, carryover); + RlcDebug("Header is end-aligned, overwrite header.li[%d]=%d", header.N_li, carryover); header.li[header.N_li] = carryover; header.N_li++; consumed_bytes += carryover; @@ -1925,7 +1912,7 @@ bool rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* pdu, rlc_am header.p |= it->header.p; } - logger->debug("Finished header reconstruction of %zd segments", pdu->segments.size()); + RlcDebug("Finished header reconstruction of %zd segments", pdu->segments.size()); // Copy data unique_byte_buffer_t full_pdu = srsran::make_byte_buffer(); @@ -1934,7 +1921,7 @@ bool rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* pdu, rlc_am srsran::console("Fatal Error: Could not allocate PDU in add_segment_and_check()\n"); exit(-1); #else - logger->error("Fatal Error: Could not allocate PDU in add_segment_and_check()"); + RlcError("Fatal Error: Could not allocate PDU in add_segment_and_check()"); return false; #endif } @@ -1970,7 +1957,7 @@ bool rlc_am_lte_rx::inside_rx_window(const int16_t sn) void rlc_am_lte_rx::debug_state() { - 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); + RlcDebug("vr_r = %d, vr_mr = %d, vr_x = %d, vr_ms = %d, vr_h = %d", vr_r, vr_mr, vr_x, vr_ms, vr_h); } } // namespace srsran diff --git a/lib/src/rlc/rlc_am_nr.cc b/lib/src/rlc/rlc_am_nr.cc index b75f1aace..ba1e30328 100644 --- a/lib/src/rlc/rlc_am_nr.cc +++ b/lib/src/rlc/rlc_am_nr.cc @@ -21,11 +21,6 @@ #define RLC_AM_NR_WINDOW_SIZE 2048 -#define Debug(fmt, ...) logger->debug("%s: " fmt, rb_name, ##__VA_ARGS__) -#define Info(fmt, ...) logger->info("%s: " fmt, rb_name, ##__VA_ARGS__) -#define Warning(fmt, ...) logger->warning("%s: " fmt, rb_name, ##__VA_ARGS__) -#define Error(fmt, ...) logger->error("%s: " fmt, rb_name, ##__VA_ARGS__) - namespace srsran { const static uint32_t max_tx_queue_size = 256; @@ -36,7 +31,7 @@ const static uint32_t max_tx_queue_size = 256; /*************************************************************************** * Tx subclass implementation ***************************************************************************/ -rlc_am_nr_tx::rlc_am_nr_tx(rlc_am* parent_) : parent(parent_), rlc_am_base_tx(&parent_->logger) {} +rlc_am_nr_tx::rlc_am_nr_tx(rlc_am* parent_) : parent(parent_), rlc_am_base_tx(parent_->logger) {} bool rlc_am_nr_tx::configure(const rlc_config_t& cfg_) { @@ -44,14 +39,14 @@ bool rlc_am_nr_tx::configure(const rlc_config_t& cfg_) rb_name = parent->rb_name; if (cfg.tx_sn_field_length != rlc_am_nr_sn_size_t::size12bits) { - Warning("RLC AM NR only supports 12 bit SN length."); + RlcWarning("RLC AM NR only supports 12 bit SN length."); return false; } if (cfg_.tx_queue_length > max_tx_queue_size) { - Error("configuring tx queue length of %d PDUs too big. Maximum value is %d.", - cfg_.tx_queue_length, - max_tx_queue_size); + RlcError("configuring tx queue length of %d PDUs too big. Maximum value is %d.", + cfg_.tx_queue_length, + max_tx_queue_size); return false; } @@ -62,7 +57,7 @@ bool rlc_am_nr_tx::configure(const rlc_config_t& cfg_) tx_enabled = true; - Debug("RLC AM NR tx entity configured."); + RlcDebug("RLC AM NR tx entity configured."); return true; } @@ -77,30 +72,30 @@ uint32_t rlc_am_nr_tx::read_pdu(uint8_t* payload, uint32_t nof_bytes) std::lock_guard lock(mutex); if (not tx_enabled) { - Debug("RLC entity not active. Not generating PDU."); + RlcDebug("RLC entity not active. Not generating PDU."); return 0; } - Debug("MAC opportunity - bytes=%d, tx_window size=%zu PDUs", nof_bytes, tx_window.size()); + RlcDebug("MAC opportunity - bytes=%d, tx_window size=%zu PDUs", nof_bytes, tx_window.size()); // Tx STATUS if requested if (do_status()) { unique_byte_buffer_t tx_pdu = srsran::make_byte_buffer(); if (tx_pdu == nullptr) { - Error("couldn't allocate PDU in %s().", __FUNCTION__); + RlcError("couldn't allocate PDU in %s().", __FUNCTION__); return 0; } build_status_pdu(tx_pdu.get(), nof_bytes); memcpy(payload, tx_pdu->msg, tx_pdu->N_bytes); - Debug("status PDU built - %d bytes", tx_pdu->N_bytes); + RlcDebug("status PDU built - %d bytes", tx_pdu->N_bytes); return tx_pdu->N_bytes; } // Retransmit if required if (not retx_queue.empty()) { - Info("re-transmission required. Retransmission queue size: %d", retx_queue.size()); + RlcInfo("re-transmission required. Retransmission queue size: %d", retx_queue.size()); unique_byte_buffer_t tx_pdu = srsran::make_byte_buffer(); if (tx_pdu == nullptr) { - Error("couldn't allocate PDU in %s().", __FUNCTION__); + RlcError("couldn't allocate PDU in %s().", __FUNCTION__); return 0; } int retx_err = build_retx_pdu(tx_pdu, nof_bytes); @@ -114,8 +109,8 @@ uint32_t rlc_am_nr_tx::read_pdu(uint8_t* payload, uint32_t nof_bytes) if (sdu_under_segmentation.rlc_sn != INVALID_RLC_SN) { if (not tx_window.has_sn(sdu_under_segmentation.rlc_sn)) { sdu_under_segmentation.rlc_sn = INVALID_RLC_SN; - Error("SDU currently being segmented does not exist in tx_window. Aborting segmentation SN=%d", - sdu_under_segmentation.rlc_sn); + RlcError("SDU currently being segmented does not exist in tx_window. Aborting segmentation SN=%d", + sdu_under_segmentation.rlc_sn); return 0; } return build_continuation_sdu_segment(tx_window[sdu_under_segmentation.rlc_sn], payload, nof_bytes); @@ -123,21 +118,21 @@ uint32_t rlc_am_nr_tx::read_pdu(uint8_t* payload, uint32_t nof_bytes) // Check whether there is something to TX if (tx_sdu_queue.is_empty()) { - Info("no data available to be sent"); + RlcInfo("no data available to be sent"); return 0; } // Read new SDU from TX queue unique_byte_buffer_t tx_sdu; - Debug("reading from RLC SDU queue. Queue size %d", tx_sdu_queue.size()); + RlcDebug("reading from RLC SDU queue. Queue size %d", tx_sdu_queue.size()); do { tx_sdu = tx_sdu_queue.read(); } while (tx_sdu == nullptr && tx_sdu_queue.size() != 0); if (tx_sdu != nullptr) { - Debug("read RLC SDU - %d bytes", tx_sdu->N_bytes); + RlcDebug("read RLC SDU - %d bytes", tx_sdu->N_bytes); } else { - Debug("no SDUs left in the tx queue."); + RlcDebug("no SDUs left in the tx queue."); return 0; } @@ -146,13 +141,13 @@ uint32_t rlc_am_nr_tx::read_pdu(uint8_t* payload, uint32_t nof_bytes) rlc_amd_tx_pdu_nr& tx_pdu = tx_window.add_pdu(st.tx_next); tx_pdu.buf = srsran::make_byte_buffer(); if (tx_pdu.buf == nullptr) { - Error("couldn't allocate PDU in %s().", __FUNCTION__); + RlcError("couldn't allocate PDU in %s().", __FUNCTION__); return 0; } // Segment new SDU if necessary if (tx_sdu->N_bytes + min_hdr_size > nof_bytes) { - Info("trying to build PDU segment from SDU."); + RlcInfo("trying to build PDU segment from SDU."); return build_new_sdu_segment(std::move(tx_sdu), tx_pdu, payload, nof_bytes); } @@ -167,19 +162,19 @@ uint32_t rlc_am_nr_tx::read_pdu(uint8_t* payload, uint32_t nof_bytes) hdr.sn_size = rlc_am_nr_sn_size_t::size12bits; hdr.sn = st.tx_next; tx_pdu.header = hdr; - log_rlc_am_nr_pdu_header_to_string(logger->info, hdr); + log_rlc_am_nr_pdu_header_to_string(logger.info, hdr); // Write header uint32_t len = rlc_am_nr_write_data_pdu_header(hdr, tx_sdu.get()); if (len > nof_bytes) { - Error("error writing AMD PDU header"); + RlcError("error writing AMD PDU header"); } // Update TX Next st.tx_next = (st.tx_next + 1) % MOD; memcpy(payload, tx_sdu->msg, tx_sdu->N_bytes); - Debug("wrote RLC PDU - %d bytes", tx_sdu->N_bytes); + RlcDebug("wrote RLC PDU - %d bytes", tx_sdu->N_bytes); return tx_sdu->N_bytes; } @@ -189,21 +184,21 @@ int rlc_am_nr_tx::build_new_sdu_segment(unique_byte_buffer_t tx_sdu, uint8_t* payload, uint32_t nof_bytes) { - Info("creating new SDU segment. Tx SDU (%d B), nof_bytes=%d B ", tx_sdu->N_bytes, nof_bytes); + RlcInfo("creating new SDU segment. Tx SDU (%d B), nof_bytes=%d B ", tx_sdu->N_bytes, nof_bytes); // Sanity check: can this SDU be sent this in a single PDU? if ((tx_sdu->N_bytes + min_hdr_size) < nof_bytes) { - Error("calling build_new_sdu_segment(), but there are enough bytes to tx in a single PDU. Tx SDU (%d B), " - "nof_bytes=%d B ", - tx_sdu->N_bytes, - nof_bytes); + RlcError("calling build_new_sdu_segment(), but there are enough bytes to tx in a single PDU. Tx SDU (%d B), " + "nof_bytes=%d B ", + tx_sdu->N_bytes, + nof_bytes); return 0; } // Sanity check: can this SDU be sent considering header overhead? if (nof_bytes <= min_hdr_size) { // Small header as SO is not present - Error("cannot build new sdu_segment, there are not enough bytes allocated to tx header plus data. nof_bytes=%d", - nof_bytes); + RlcError("cannot build new sdu_segment, there are not enough bytes allocated to tx header plus data. nof_bytes=%d", + nof_bytes); return 0; } @@ -216,12 +211,12 @@ int rlc_am_nr_tx::build_new_sdu_segment(unique_byte_buffer_t tx_sdu, hdr.sn = st.tx_next; hdr.so = 0; tx_pdu.header = hdr; - log_rlc_am_nr_pdu_header_to_string(logger->info, hdr); + log_rlc_am_nr_pdu_header_to_string(logger.info, hdr); // Write header uint32_t hdr_len = rlc_am_nr_write_data_pdu_header(hdr, payload); if (hdr_len >= nof_bytes || hdr_len != min_hdr_size) { - Error("error writing AMD PDU header"); + RlcError("error writing AMD PDU header"); return 0; } @@ -243,18 +238,18 @@ int rlc_am_nr_tx::build_new_sdu_segment(unique_byte_buffer_t tx_sdu, int rlc_am_nr_tx::build_continuation_sdu_segment(rlc_amd_tx_pdu_nr& tx_pdu, uint8_t* payload, uint32_t nof_bytes) { - Info("continuing SDU segment. SN=%d, Tx SDU (%d B), nof_bytes=%d B ", - sdu_under_segmentation.rlc_sn, - sdu_under_segmentation.buf->N_bytes, - nof_bytes); - - // Sanity check: is there an initial SDU segment? - if (tx_pdu.segment_list.empty()) { - Error("build_continuation_sdu_segment was called, but there was no initial segment. SN=%d, Tx SDU (%d B), " - "nof_bytes=%d B ", + RlcInfo("continuing SDU segment. SN=%d, Tx SDU (%d B), nof_bytes=%d B ", sdu_under_segmentation.rlc_sn, sdu_under_segmentation.buf->N_bytes, nof_bytes); + + // Sanity check: is there an initial SDU segment? + if (tx_pdu.segment_list.empty()) { + RlcError("build_continuation_sdu_segment was called, but there was no initial segment. SN=%d, Tx SDU (%d B), " + "nof_bytes=%d B ", + sdu_under_segmentation.rlc_sn, + sdu_under_segmentation.buf->N_bytes, + nof_bytes); sdu_under_segmentation.rlc_sn = INVALID_RLC_SN; sdu_under_segmentation.buf = nullptr; return 0; @@ -262,19 +257,19 @@ int rlc_am_nr_tx::build_continuation_sdu_segment(rlc_amd_tx_pdu_nr& tx_pdu, uint // Sanity check: can this SDU be sent considering header overhead? if ((max_hdr_size + 1) < nof_bytes) { // Larger header size, as SO is present - Error("cannot build new sdu_segment, there are not enough bytes allocated to tx header plus data. nof_bytes=%d", - nof_bytes); + RlcError("cannot build new sdu_segment, there are not enough bytes allocated to tx header plus data. nof_bytes=%d", + nof_bytes); return 0; } // Can the rest of the SDU be sent on a single segment PDU? const rlc_amd_tx_pdu_nr::pdu_segment& seg = tx_pdu.segment_list.back(); uint32_t last_byte = seg.so + seg.payload_len; - Debug("continuing SDU segment. SN=%d, last byte transmitted %d", tx_pdu.rlc_sn, last_byte); + RlcDebug("continuing SDU segment. SN=%d, last byte transmitted %d", tx_pdu.rlc_sn, last_byte); // Sanity check: last byte must be smaller than SDU if (sdu_under_segmentation.buf->N_bytes < last_byte) { - Error("last byte transmitted larger than SDU len. SDU len=%d B, last_byte=%d B", tx_pdu.buf->N_bytes, last_byte); + RlcError("last byte transmitted larger than SDU len. SDU len=%d B, last_byte=%d B", tx_pdu.buf->N_bytes, last_byte); return 0; } @@ -283,18 +278,18 @@ int rlc_am_nr_tx::build_continuation_sdu_segment(rlc_amd_tx_pdu_nr& tx_pdu, uint rlc_nr_si_field_t si = {}; if (segment_payload_full_len > nof_bytes) { - Info("grant is not large enough for full SDU. " - "SDU bytes left %d, nof_bytes %d, ", - segment_payload_full_len, - nof_bytes); + RlcInfo("grant is not large enough for full SDU. " + "SDU bytes left %d, nof_bytes %d, ", + segment_payload_full_len, + nof_bytes); si = rlc_nr_si_field_t::neither_first_nor_last_segment; segment_payload_len = nof_bytes - max_hdr_size; segment_payload_full_len = nof_bytes; } else { - Info("grant is large enough for full SDU." - "SDU bytes left %d, nof_bytes %d, ", - segment_payload_full_len, - nof_bytes); + RlcInfo("grant is large enough for full SDU." + "SDU bytes left %d, nof_bytes %d, ", + segment_payload_full_len, + nof_bytes); si = rlc_nr_si_field_t::last_segment; } @@ -307,12 +302,12 @@ int rlc_am_nr_tx::build_continuation_sdu_segment(rlc_amd_tx_pdu_nr& tx_pdu, uint hdr.sn = st.tx_next; hdr.so = last_byte; tx_pdu.header = hdr; - log_rlc_am_nr_pdu_header_to_string(logger->info, hdr); + log_rlc_am_nr_pdu_header_to_string(logger.info, hdr); // Write header uint32_t hdr_len = rlc_am_nr_write_data_pdu_header(hdr, payload); if (hdr_len >= nof_bytes || hdr_len != max_hdr_size) { - Error("error writing AMD PDU header"); + RlcError("error writing AMD PDU header"); return 0; } @@ -327,11 +322,11 @@ int rlc_am_nr_tx::build_continuation_sdu_segment(rlc_amd_tx_pdu_nr& tx_pdu, uint tx_pdu.segment_list.push_back(segment_info); if (si == rlc_nr_si_field_t::neither_first_nor_last_segment) { - Info("grant is not large enough for full SDU." - "Storing SDU segment info"); + RlcInfo("grant is not large enough for full SDU." + "Storing SDU segment info"); } else { - Info("grant is large enough for full SDU." - "Removing current SDU info"); + RlcInfo("grant is large enough for full SDU." + "Removing current SDU info"); sdu_under_segmentation.rlc_sn = INVALID_RLC_SN; sdu_under_segmentation.buf = nullptr; } @@ -343,7 +338,7 @@ int rlc_am_nr_tx::build_retx_pdu(unique_byte_buffer_t& tx_pdu, uint32_t nof_byte { // Check there is at least 1 element before calling front() if (retx_queue.empty()) { - Error("in build_retx_pdu(): retx_queue is empty"); + RlcError("in build_retx_pdu(): retx_queue is empty"); return SRSRAN_ERROR; } @@ -351,12 +346,12 @@ int rlc_am_nr_tx::build_retx_pdu(unique_byte_buffer_t& tx_pdu, uint32_t nof_byte // Sanity check - drop any retx SNs not present in tx_window while (not tx_window.has_sn(retx.sn)) { - Warning("SN=%d not in tx window. Ignoring retx.", retx.sn); + RlcWarning("SN=%d not in tx window. Ignoring retx.", retx.sn); retx_queue.pop(); if (!retx_queue.empty()) { retx = retx_queue.front(); } else { - Warning("empty retx queue, cannot provide retx PDU"); + RlcWarning("empty retx queue, cannot provide retx PDU"); return SRSRAN_ERROR; } } @@ -367,7 +362,7 @@ int rlc_am_nr_tx::build_retx_pdu(unique_byte_buffer_t& tx_pdu, uint32_t nof_byte // Check if we exceed allocated number of bytes if (hdr_len + tx_window[retx.sn].buf->N_bytes > nof_bytes) { - Warning("segmentation not supported yet. Cannot provide retx PDU"); + RlcWarning("segmentation not supported yet. Cannot provide retx PDU"); return SRSRAN_ERROR; } // TODO Consider re-segmentation @@ -377,16 +372,15 @@ int rlc_am_nr_tx::build_retx_pdu(unique_byte_buffer_t& tx_pdu, uint32_t nof_byte retx_queue.pop(); - logger->info(tx_window[retx.sn].buf->msg, - tx_window[retx.sn].buf->N_bytes, - "%s Original SDU SN=%d (%d B) (attempt %d/%d)", - parent->rb_name, - retx.sn, - tx_window[retx.sn].buf->N_bytes, - tx_window[retx.sn].retx_count + 1, - cfg.max_retx_thresh); - logger->info(tx_pdu->msg, tx_pdu->N_bytes, "%s retx PDU SN=%d (%d B)", parent->rb_name, retx.sn, tx_pdu->N_bytes); - log_rlc_am_nr_pdu_header_to_string(logger->debug, new_header); + RlcHexInfo(tx_window[retx.sn].buf->msg, + tx_window[retx.sn].buf->N_bytes, + "Original SDU SN=%d (%d B) (attempt %d/%d)", + retx.sn, + tx_window[retx.sn].buf->N_bytes, + tx_window[retx.sn].retx_count + 1, + cfg.max_retx_thresh); + RlcHexInfo(tx_pdu->msg, tx_pdu->N_bytes, "retx PDU SN=%d (%d B)", retx.sn, tx_pdu->N_bytes); + log_rlc_am_nr_pdu_header_to_string(logger.debug, new_header); // debug_state(); return SRSRAN_SUCCESS; @@ -394,18 +388,18 @@ int rlc_am_nr_tx::build_retx_pdu(unique_byte_buffer_t& tx_pdu, uint32_t nof_byte uint32_t rlc_am_nr_tx::build_status_pdu(byte_buffer_t* payload, uint32_t nof_bytes) { - Info("generating status PDU. Bytes available:%d", nof_bytes); + RlcInfo("generating status PDU. Bytes available:%d", nof_bytes); rlc_am_nr_status_pdu_t tx_status; int pdu_len = rx->get_status_pdu(&tx_status, nof_bytes); if (pdu_len == SRSRAN_ERROR) { - Debug("deferred status PDU. Cause: Failed to acquire rx lock"); + RlcDebug("deferred status PDU. Cause: Failed to acquire rx lock"); pdu_len = 0; } else if (pdu_len > 0 && nof_bytes >= static_cast(pdu_len)) { - Debug("generated status PDU. Bytes:%d", pdu_len); - log_rlc_am_nr_status_pdu_to_string(logger->info, "%s tx status PDU - %s", &tx_status, rb_name); + RlcDebug("generated status PDU. Bytes:%d", pdu_len); + log_rlc_am_nr_status_pdu_to_string(logger.info, "%s tx status PDU - %s", &tx_status, rb_name); pdu_len = rlc_am_nr_write_status_pdu(tx_status, rlc_am_nr_sn_size_t::size12bits, payload); } else { - Info("cannot tx status PDU - %d bytes available, %d bytes required", nof_bytes, pdu_len); + RlcInfo("cannot tx status PDU - %d bytes available, %d bytes required", nof_bytes, pdu_len); pdu_len = 0; } @@ -419,9 +413,9 @@ void rlc_am_nr_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_bytes) } rlc_am_nr_status_pdu_t status = {}; - logger->debug(payload, nof_bytes, "%s Rx control PDU", parent->rb_name); + RlcHexDebug(payload, nof_bytes, "%s Rx control PDU", parent->rb_name); rlc_am_nr_read_status_pdu(payload, nof_bytes, rlc_am_nr_sn_size_t::size12bits, &status); - log_rlc_am_nr_status_pdu_to_string(logger->info, "%s Rx Status PDU: %s", &status, parent->rb_name); + log_rlc_am_nr_status_pdu_to_string(logger.info, "%s Rx Status PDU: %s", &status, parent->rb_name); // Local variables for handling Status PDU will be updated with lock /* * - if the SN of the corresponding RLC SDU falls within the range @@ -434,7 +428,7 @@ void rlc_am_nr_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_bytes) ? status.ack_sn : status.nacks[0].nack_sn - 1; // Stop processing ACKs at the first NACK, if it exists. if (stop_sn > st.tx_next) { - Error("Received ACK or NACK larger than TX_NEXT. Ignoring status report"); + RlcError("Received ACK or NACK larger than TX_NEXT. Ignoring status report"); return; } for (uint32_t sn = st.tx_next_ack; sn < stop_sn; sn++) { @@ -443,7 +437,7 @@ void rlc_am_nr_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_bytes) st.tx_next_ack = sn + 1; // TODO notify PDCP } else { - Error("Missing ACKed SN from TX window"); + RlcError("Missing ACKed SN from TX window"); break; } } @@ -495,31 +489,31 @@ uint32_t rlc_am_nr_tx::get_buffer_state() void rlc_am_nr_tx::get_buffer_state(uint32_t& n_bytes_new, uint32_t& n_bytes_prio) { std::lock_guard lock(mutex); - Debug("buffer state - do_status=%s", do_status() ? "yes" : "no"); + RlcDebug("buffer state - do_status=%s", do_status() ? "yes" : "no"); // Bytes needed for status report if (do_status()) { n_bytes_prio += rx->get_status_pdu_length(); - Debug("buffer state - total status report: %d bytes", n_bytes_prio); + RlcDebug("buffer state - total status report: %d bytes", n_bytes_prio); } // Bytes needed for retx if (not retx_queue.empty()) { rlc_amd_retx_t& retx = retx_queue.front(); - Debug("buffer state - retx - SN=%d, Segment: %s, %d:%d", - retx.sn, - retx.is_segment ? "true" : "false", - retx.so_start, - retx.so_end); + RlcDebug("buffer state - retx - SN=%d, Segment: %s, %d:%d", + retx.sn, + retx.is_segment ? "true" : "false", + retx.so_start, + retx.so_end); if (tx_window.has_sn(retx.sn)) { int req_bytes = retx.so_end - retx.so_start; int hdr_req_bytes = retx.is_segment ? max_hdr_size : min_hdr_size; // Segmentation not supported yet if (req_bytes <= 0) { - Error("in get_buffer_state(): Removing retx with SN=%d from queue", retx.sn); + RlcError("in get_buffer_state(): Removing retx with SN=%d from queue", retx.sn); retx_queue.pop(); } else { n_bytes_prio += (req_bytes + hdr_req_bytes); - Debug("buffer state - retx: %d bytes", n_bytes_prio); + RlcDebug("buffer state - retx: %d bytes", n_bytes_prio); } } } @@ -530,10 +524,10 @@ void rlc_am_nr_tx::get_buffer_state(uint32_t& n_bytes_new, uint32_t& n_bytes_pri // Room needed for fixed header of data PDUs n_bytes_new += min_hdr_size * n_sdus; - Debug("total buffer state - %d SDUs (%d B)", n_sdus, n_bytes_new + n_bytes_prio); + RlcDebug("total buffer state - %d SDUs (%d B)", n_sdus, n_bytes_new + n_bytes_prio); if (bsr_callback) { - Debug("calling BSR callback - %d new_tx, %d priority bytes", n_bytes_new, n_bytes_prio); + RlcDebug("calling BSR callback - %d new_tx, %d priority bytes", n_bytes_new, n_bytes_prio); bsr_callback(parent->lcid, n_bytes_new, n_bytes_prio); } } @@ -594,7 +588,7 @@ rlc_am_nr_rx::rlc_am_nr_rx(rlc_am* parent_) : pool(byte_buffer_pool::get_instance()), status_prohibit_timer(parent->timers->get_unique_timer()), reassembly_timer(parent->timers->get_unique_timer()), - rlc_am_base_rx(parent_, &parent_->logger) + rlc_am_base_rx(parent_, parent_->logger) {} bool rlc_am_nr_rx::configure(const rlc_config_t& cfg_) @@ -610,12 +604,12 @@ bool rlc_am_nr_rx::configure(const rlc_config_t& cfg_) // Configure t_reassembly timer if (cfg.t_reassembly > 0) { reassembly_timer.set(static_cast(cfg.t_reassembly), [this](uint32_t timerid) { timer_expired(timerid); }); - Info("configured reassembly timer. t-Reassembly=%d ms", cfg.t_reassembly); + RlcInfo("configured reassembly timer. t-Reassembly=%d ms", cfg.t_reassembly); } mod_nr = (cfg.rx_sn_field_length == rlc_am_nr_sn_size_t::size12bits) ? 4096 : 262144; - Debug("RLC AM NR configured rx entity."); + RlcDebug("RLC AM NR configured rx entity."); return true; } @@ -633,18 +627,18 @@ void rlc_am_nr_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_bytes) rlc_am_nr_pdu_header_t header = {}; uint32_t hdr_len = rlc_am_nr_read_data_pdu_header(payload, nof_bytes, rlc_am_nr_sn_size_t::size12bits, &header); - logger->info(payload, nof_bytes, "%s Rx data PDU SN=%d (%d B)", parent->rb_name, header.sn, nof_bytes); - log_rlc_am_nr_pdu_header_to_string(logger->debug, header); + RlcHexInfo(payload, nof_bytes, "Rx data PDU SN=%d (%d B)", header.sn, nof_bytes); + log_rlc_am_nr_pdu_header_to_string(logger.debug, header); // Check whether SDU is within Rx Window if (!inside_rx_window(header.sn)) { - Info("SN=%d outside rx window [%d:%d] - discarding", header.sn, st.rx_next, st.rx_next + RLC_AM_NR_WINDOW_SIZE); + RlcInfo("SN=%d outside rx window [%d:%d] - discarding", header.sn, st.rx_next, st.rx_next + RLC_AM_NR_WINDOW_SIZE); return; } // Section 5.2.3.2.2, discard duplicate PDUs if (rx_window.has_sn(header.sn) && rx_window[header.sn].fully_received) { - Info("discarding duplicate SN=%d", header.sn); + RlcInfo("discarding duplicate SN=%d", header.sn); return; } @@ -663,7 +657,7 @@ void rlc_am_nr_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_bytes) // Check poll bit if (header.p) { - Info("status packet requested through polling bit"); + RlcInfo("status packet requested through polling bit"); do_status = true; status_prohibit_timer.stop(); } @@ -767,7 +761,7 @@ int rlc_am_nr_rx::handle_full_data_sdu(const rlc_am_nr_pdu_header_t& header, con rlc_amd_rx_sdu_nr_t& rx_sdu = rx_window.add_pdu(header.sn); rx_sdu.buf = srsran::make_byte_buffer(); if (rx_sdu.buf == nullptr) { - Error("fatal error. Couldn't allocate PDU in %s.", __FUNCTION__); + RlcError("fatal error. Couldn't allocate PDU in %s.", __FUNCTION__); rx_window.remove_pdu(header.sn); return SRSRAN_ERROR; } @@ -775,7 +769,7 @@ int rlc_am_nr_rx::handle_full_data_sdu(const rlc_am_nr_pdu_header_t& header, con // check available space for payload if (nof_bytes > rx_sdu.buf->get_tailroom()) { - Error("discarding SN=%d of size %d B (available space %d B)", header.sn, nof_bytes, rx_sdu.buf->get_tailroom()); + RlcError("discarding SN=%d of size %d B (available space %d B)", header.sn, nof_bytes, rx_sdu.buf->get_tailroom()); rx_window.remove_pdu(header.sn); return SRSRAN_ERROR; } @@ -791,7 +785,7 @@ int rlc_am_nr_rx::handle_segment_data_sdu(const rlc_am_nr_pdu_header_t& header, uint32_t nof_bytes) { if (header.si == rlc_nr_si_field_t::full_sdu) { - Error("called %s but the SI implies a full SDU. SN=%d", __FUNCTION__, header.sn); + RlcError("called %s but the SI implies a full SDU. SN=%d", __FUNCTION__, header.sn); return SRSRAN_ERROR; } @@ -799,11 +793,11 @@ int rlc_am_nr_rx::handle_segment_data_sdu(const rlc_am_nr_pdu_header_t& header, // Log SDU segment reception if (header.si == rlc_nr_si_field_t::first_segment) { // Check whether it's a full SDU - Debug("Initial segment PDU. SN=%d.", header.sn); + RlcDebug("Initial segment PDU. SN=%d.", header.sn); } else if (header.si == rlc_nr_si_field_t::neither_first_nor_last_segment) { - Debug("Middle segment PDU. SN=%d.", header.sn); + RlcDebug("Middle segment PDU. SN=%d.", header.sn); } else if (header.si == rlc_nr_si_field_t::last_segment) { - Debug("Final segment PDU. SN=%d.", header.sn); + RlcDebug("Final segment PDU. SN=%d.", header.sn); } // Add a new SDU to the RX window if necessary @@ -814,7 +808,7 @@ int rlc_am_nr_rx::handle_segment_data_sdu(const rlc_am_nr_pdu_header_t& header, pdu_segment.header = header; pdu_segment.buf = srsran::make_byte_buffer(); if (pdu_segment.buf == nullptr) { - Error("fatal error. Couldn't allocate PDU in %s.", __FUNCTION__); + RlcError("fatal error. Couldn't allocate PDU in %s.", __FUNCTION__); return SRSRAN_ERROR; } memcpy(pdu_segment.buf->msg, payload + hdr_len, nof_bytes - hdr_len); // Don't copy header @@ -826,10 +820,10 @@ int rlc_am_nr_rx::handle_segment_data_sdu(const rlc_am_nr_pdu_header_t& header, // Check weather all segments have been received rx_sdu.fully_received = have_all_segments_been_received(rx_sdu.segments); if (rx_sdu.fully_received) { - Info("Fully received segmented SDU. SN=%d.", header.sn); + RlcInfo("Fully received segmented SDU. SN=%d.", header.sn); rx_sdu.buf = srsran::make_byte_buffer(); if (rx_sdu.buf == nullptr) { - Error("fatal error. Couldn't allocate PDU in %s.", __FUNCTION__); + RlcError("fatal error. Couldn't allocate PDU in %s.", __FUNCTION__); rx_window.remove_pdu(header.sn); return SRSRAN_ERROR; } @@ -898,13 +892,13 @@ void rlc_am_nr_rx::timer_expired(uint32_t timeout_id) // Status Prohibit if (status_prohibit_timer.is_valid() && status_prohibit_timer.id() == timeout_id) { - Debug("Status prohibit timer expired after %dms", status_prohibit_timer.duration()); + RlcDebug("Status prohibit timer expired after %dms", status_prohibit_timer.duration()); return; } // Reassembly if (reassembly_timer.is_valid() && reassembly_timer.id() == timeout_id) { - Debug("Reassembly timer expired after %dms", reassembly_timer.duration()); + RlcDebug("Reassembly timer expired after %dms", reassembly_timer.duration()); /* * 5.2.3.2.4 Actions when t-Reassembly expires: * - update RX_Highest_Status to the SN of the first RLC SDU with SN >= RX_Next_Status_Trigger for which not @@ -1007,10 +1001,10 @@ bool rlc_am_nr_rx::have_all_segments_been_received(const std::listN_bytes; srsran::error_type ret = ul_queue.try_write(std::move(sdu)); if (ret) { - logger.info(msg_ptr, - nof_bytes, - "%s Tx SDU, queue size=%d, bytes=%d", - rrc->get_rb_name(lcid), - ul_queue.size(), - ul_queue.size_bytes()); + RlcHexInfo(msg_ptr, + nof_bytes, + "%s Tx SDU, queue size=%d, bytes=%d", + rrc->get_rb_name(lcid), + ul_queue.size(), + ul_queue.size_bytes()); } else { - logger.warning(ret.error()->msg, - ret.error()->N_bytes, - "[Dropped SDU] %s Tx SDU, queue size=%d, bytes=%d", - rrc->get_rb_name(lcid), - ul_queue.size(), - ul_queue.size_bytes()); + RlcHexWarning(ret.error()->msg, + ret.error()->N_bytes, + "[Dropped SDU] %s Tx SDU, queue size=%d, bytes=%d", + rrc->get_rb_name(lcid), + ul_queue.size(), + ul_queue.size_bytes()); } } else { @@ -161,13 +161,12 @@ uint32_t rlc_tm::read_pdu(uint8_t* payload, uint32_t nof_bytes) pdu_size = buf->N_bytes; memcpy(payload, buf->msg, buf->N_bytes); RlcDebug("Complete SDU scheduled for tx. Stack latency: %" PRIu64 " us", (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), - srsran::to_string(rlc_mode_t::tm), - ul_queue.size(), - ul_queue.size_bytes()); + RlcHexInfo(payload, + pdu_size, + "Tx %s PDU, queue size=%d, bytes=%d", + srsran::to_string(rlc_mode_t::tm), + ul_queue.size(), + ul_queue.size_bytes()); std::lock_guard lock(metrics_mutex); metrics.num_tx_pdu_bytes += pdu_size; diff --git a/lib/src/rlc/rlc_um_base.cc b/lib/src/rlc/rlc_um_base.cc index 1fcafaef9..b39e7d34c 100644 --- a/lib/src/rlc/rlc_um_base.cc +++ b/lib/src/rlc/rlc_um_base.cc @@ -266,12 +266,7 @@ void rlc_um_base::rlc_um_base_tx::set_bsr_callback(bsr_callback_t callback) void rlc_um_base::rlc_um_base_tx::write_sdu(unique_byte_buffer_t sdu) { if (sdu) { - 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()); + RlcHexInfo(sdu->msg, sdu->N_bytes, "Tx SDU (%d B, tx_sdu_queue_len=%d)", sdu->N_bytes, tx_sdu_queue.size()); tx_sdu_queue.write(std::move(sdu)); } else { RlcWarning("NULL SDU pointer in write_sdu()"); @@ -285,16 +280,15 @@ int rlc_um_base::rlc_um_base_tx::try_write_sdu(unique_byte_buffer_t sdu) uint32_t nof_bytes = sdu->N_bytes; srsran::error_type ret = tx_sdu_queue.try_write(std::move(sdu)); if (ret) { - 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()); + RlcHexInfo(msg_ptr, nof_bytes, "Tx SDU (%d B, tx_sdu_queue_len=%d)", nof_bytes, tx_sdu_queue.size()); return SRSRAN_SUCCESS; } else { - 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()); + RlcHexWarning(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 { RlcWarning("NULL SDU pointer in write_sdu()");