5g-team
/
srsRAN_4G
mirror of https://github.com/pvnis/srsRAN_4G.git
2
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

lib,rlc: added macros for hex logging that automatically add the rb_name. changed logging to use new macros in multiple places.

Browse Source
master
Pedro Alvarez 3 years ago
parent b687072815
commit 0f4b64f13f
7 changed files with 384 additions and 405 deletions
Show Stats Download Patch File Download Diff File

8
lib/include/srsran/rlc/rlc_am_base.h
Unescape Escape View File

@ -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;

5
lib/include/srsran/rlc/rlc_common.h
Unescape Escape View File

@ -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,

8
lib/src/rlc/rlc_am_base.cc
Unescape Escape View File

@ -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,10 +221,10 @@ int rlc_am::rlc_am_base_tx::write_sdu(unique_byte_buffer_t sdu)
uint32_t nof_bytes = sdu->N_bytes;
srsran::error_type<unique_byte_buffer_t> 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,
RlcHexWarning(ret.error()->msg,
ret.error()->N_bytes,
"[Dropped SDU] %s Tx SDU (%d B, tx_sdu_queue_len=%d)",
rb_name,
@ -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;
}

295
lib/src/rlc/rlc_am_lte.cc
Unescape Escape View File

@ -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<rlc_am_lte_rx*>(parent->rx_base.get());
}
@ -46,7 +46,7 @@ bool rlc_am_lte_tx::configure(const rlc_config_t& cfg_)
{
std::lock_guard<std::mutex> 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.",
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,8 +207,7 @@ 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,
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(),
@ -217,14 +216,13 @@ void rlc_am_lte_tx::get_buffer_state_nolock(uint32_t& n_bytes_newtx, uint32_t& n
// 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,
RlcDebug("%s Buffer state - retx - SN=%d, Segment: %s, %d:%d",
retx.sn,
retx.is_segment ? "true" : "false",
retx.so_start,
@ -232,11 +230,11 @@ void rlc_am_lte_tx::get_buffer_state_nolock(uint32_t& n_bytes_newtx, uint32_t& n
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<std::mutex> 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<uint32_t>(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<uint32_t>(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<uint32_t>(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<int>(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,
RlcHexInfo(payload,
tx_window[retx.sn].buf->N_bytes,
"%s Tx PDU SN=%d (%d B) (attempt %d/%d)",
RB_NAME,
"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);
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,7 +571,7 @@ 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",
RlcInfo("%s Cannot build a PDU segment - %d bytes available, %d bytes required for header",
RB_NAME,
nof_bytes,
head_len);
@ -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,19 +687,17 @@ 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<int>(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,
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,
RlcHexInfo(payload,
pdu_len,
"%s Retx PDU segment SN=%d [so=%d] (%d B) (attempt %d/%d)",
RB_NAME,
"retx PDU segment SN=%d [so=%d] (%d B) (attempt %d/%d)",
retx.sn,
retx.so_start,
pdu_len,
@ -715,18 +710,18 @@ 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 ",
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);
@ -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,9 +841,9 @@ 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)",
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);
@ -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,7 +872,7 @@ 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 ",
RlcDebug("%s Building PDU - added SDU segment (len:%d) - pdu_space: %d, head_len: %d ",
RB_NAME,
to_move,
pdu_space,
@ -886,7 +881,7 @@ int rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes)
// 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,16 +937,16 @@ void rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_bytes)
{
std::lock_guard<std::mutex> 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.",
RlcWarning("%s Received invalid status PDU (ack_sn=%d, vt_a=%d, vt_s=%d). Dropping PDU.",
RB_NAME,
status.ack_sn,
vt_a,
@ -962,7 +957,7 @@ void rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_bytes)
// 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,8 +1013,7 @@ 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,
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,
@ -1028,10 +1021,10 @@ void rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t nof_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<std::mutex> 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<std::mutex> 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,7 +1071,7 @@ 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",
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());
@ -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<uint32_t, rlc_amd_rx_pdu>::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<uint32_t, rlc_amd_rx_pdu_segments_t>::iterator it;
logger->info(payload,
RlcHexInfo(payload,
nof_bytes,
"%s Rx data PDU segment of SN=%d (%d B), SO=%d, N_li=%d",
RB_NAME,
"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);
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,7 +1495,7 @@ 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,
RlcHexDebug(rx_window[vr_r].buf->msg,
len,
"Handling segment %d/%d of length %d B of SN=%d",
i + 1,
@ -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::milliseconds>(
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::milliseconds>(
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,15 +1602,15 @@ 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<uint32_t, rlc_amd_rx_pdu_segments_t>::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<rlc_amd_rx_pdu>::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",
RlcDebug(" Erasing segment of SN=%d SO=%d Len=%d N_li=%d",
segit->header.sn,
segit->header.so,
segit->buf->N_bytes,
@ -1668,7 +1656,7 @@ void rlc_am_lte_rx::timer_expired(uint32_t timeout_id)
{
std::lock_guard<std::mutex> 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,20 +1702,19 @@ 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)",
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);
@ -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,7 +1852,7 @@ 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)",
RlcDebug(" - (total_pdu_offset=%d, consumed_bytes=%d, header.li[i]=%d)",
total_pdu_offset,
consumed_bytes,
header.li[i]);
@ -1873,7 +1860,7 @@ bool rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* pdu, rlc_am
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)",
RlcDebug(" - adding segment %d/%d (%d B, SO=%d, carryover=%d, count=%d)",
i + 1,
it->header.N_li,
header.li[header.N_li],
@ -1884,7 +1871,7 @@ bool rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* pdu, rlc_am
count += it->header.li[i];
carryover = 0;
} else {
logger->debug(" - Skipping segment in reTx PDU segment which is already included (%d B, SO=%d)",
RlcDebug(" - Skipping segment in reTx PDU segment which is already included (%d B, SO=%d)",
it->header.li[i],
header.so);
}
@ -1896,7 +1883,7 @@ 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",
RlcDebug("Incremented carryover (it->buf->N_bytes=%d, count=%d). New carryover=%d",
it->buf->N_bytes,
count,
carryover);
@ -1904,7 +1891,7 @@ bool rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* pdu, rlc_am
// 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)",
RlcDebug("Recalculated carryover=%d (it->buf->N_bytes=%d, count=%d, header.li[header.N_li]=%d)",
carryover,
it->buf->N_bytes,
count,
@ -1913,7 +1900,7 @@ bool rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t* pdu, rlc_am
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

166
lib/src/rlc/rlc_am_nr.cc
Unescape Escape View File

@ -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,12 +39,12 @@ 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.",
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<std::mutex> 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,7 +109,7 @@ 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",
RlcError("SDU currently being segmented does not exist in tx_window. Aborting segmentation SN=%d",
sdu_under_segmentation.rlc_sn);
return 0;
}
@ -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,11 +184,11 @@ 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), "
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);
@ -202,7 +197,7 @@ int rlc_am_nr_tx::build_new_sdu_segment(unique_byte_buffer_t tx_sdu,
// 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",
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,14 +238,14 @@ 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 ",
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()) {
Error("build_continuation_sdu_segment was called, but there was no initial segment. SN=%d, Tx SDU (%d B), "
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,
@ -262,7 +257,7 @@ 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",
RlcError("cannot build new sdu_segment, there are not enough bytes allocated to tx header plus data. nof_bytes=%d",
nof_bytes);
return 0;
}
@ -270,11 +265,11 @@ int rlc_am_nr_tx::build_continuation_sdu_segment(rlc_amd_tx_pdu_nr& tx_pdu, uint
// 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,7 +278,7 @@ 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. "
RlcInfo("grant is not large enough for full SDU. "
"SDU bytes left %d, nof_bytes %d, ",
segment_payload_full_len,
nof_bytes);
@ -291,7 +286,7 @@ int rlc_am_nr_tx::build_continuation_sdu_segment(rlc_amd_tx_pdu_nr& tx_pdu, uint
segment_payload_len = nof_bytes - max_hdr_size;
segment_payload_full_len = nof_bytes;
} else {
Info("grant is large enough for full SDU."
RlcInfo("grant is large enough for full SDU."
"SDU bytes left %d, nof_bytes %d, ",
segment_payload_full_len,
nof_bytes);
@ -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,10 +322,10 @@ 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."
RlcInfo("grant is not large enough for full SDU."
"Storing SDU segment info");
} else {
Info("grant is large enough for full SDU."
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,
RlcHexInfo(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,
"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);
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_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<uint32_t>(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,18 +489,18 @@ 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<std::mutex> 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",
RlcDebug("buffer state - retx - SN=%d, Segment: %s, %d:%d",
retx.sn,
retx.is_segment ? "true" : "false",
retx.so_start,
@ -515,11 +509,11 @@ void rlc_am_nr_tx::get_buffer_state(uint32_t& n_bytes_new, uint32_t& n_bytes_pri
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<uint32_t>(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,7 +1001,7 @@ bool rlc_am_nr_rx::have_all_segments_been_received(const std::list<rlc_amd_rx_pd
*/
void rlc_am_nr_rx::debug_state()
{
Debug("RX entity state: Rx_Next %d, Rx_Next_Status_Trigger %d, Rx_Highest_Status %d, Rx_Next_Highest",
RlcDebug("RX entity state: Rx_Next %d, Rx_Next_Status_Trigger %d, Rx_Highest_Status %d, Rx_Next_Highest",
st.rx_next,
st.rx_next_status_trigger,
st.rx_highest_status,

9
lib/src/rlc/rlc_tm.cc
Unescape Escape View File

@ -80,14 +80,14 @@ void rlc_tm::write_sdu(unique_byte_buffer_t sdu)
uint32_t nof_bytes = sdu->N_bytes;
srsran::error_type<unique_byte_buffer_t> ret = ul_queue.try_write(std::move(sdu));
if (ret) {
logger.info(msg_ptr,
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,
RlcHexWarning(ret.error()->msg,
ret.error()->N_bytes,
"[Dropped SDU] %s Tx SDU, queue size=%d, bytes=%d",
rrc->get_rb_name(lcid),
@ -161,10 +161,9 @@ 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,
RlcHexInfo(payload,
pdu_size,
"%s Tx %s PDU, queue size=%d, bytes=%d",
rrc->get_rb_name(lcid),
"Tx %s PDU, queue size=%d, bytes=%d",
srsran::to_string(rlc_mode_t::tm),
ul_queue.size(),
ul_queue.size_bytes());

12
lib/src/rlc/rlc_um_base.cc
Unescape Escape View File

@ -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,11 +280,10 @@ 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<unique_byte_buffer_t> 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,
RlcHexWarning(ret.error()->msg,
ret.error()->N_bytes,
"[Dropped SDU] %s Tx SDU (%d B, tx_sdu_queue_len=%d)",
rb_name.c_str(),

Write Preview
Loading…
Cancel
Save