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: make sure TM rb name is initialized. changed rlc_um_lte to use new logging macros

Browse Source
master
Pedro Alvarez 3 years ago
parent e157806db2
commit b46c5423f0
3 changed files with 118 additions and 136 deletions
Show Stats Download Patch File Download Diff File

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

@ -44,6 +44,9 @@ rlc_am_lte_tx::rlc_am_lte_tx(rlc_am* parent_) :
bool rlc_am_lte_tx::configure(const rlc_config_t& cfg_) bool rlc_am_lte_tx::configure(const rlc_config_t& cfg_)
{ {
std::lock_guard<std::mutex> lock(mutex); std::lock_guard<std::mutex> lock(mutex);
rb_name = parent->rb_name;
if (cfg_.tx_queue_length > MAX_SDUS_PER_RLC_PDU) { if (cfg_.tx_queue_length > MAX_SDUS_PER_RLC_PDU) {
RlcError("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, cfg_.tx_queue_length,
@ -221,7 +224,7 @@ void rlc_am_lte_tx::get_buffer_state_nolock(uint32_t& n_bytes_newtx, uint32_t& n
// Bytes needed for retx // Bytes needed for retx
if (not retx_queue.empty()) { if (not retx_queue.empty()) {
rlc_amd_retx_t& retx = retx_queue.front(); rlc_amd_retx_t& retx = retx_queue.front();
RlcDebug("%s Buffer state - retx - SN=%d, Segment: %s, %d:%d", RlcDebug("Buffer state - retx - SN=%d, Segment: %s, %d:%d",
retx.sn, retx.sn,
retx.is_segment ? "true" : "false", retx.is_segment ? "true" : "false",
retx.so_start, retx.so_start,
@ -1184,6 +1187,8 @@ bool rlc_am_lte_rx::configure(const rlc_config_t& cfg_)
// TODO: add config checks // TODO: add config checks
cfg = cfg_.am; cfg = cfg_.am;
rb_name = parent->rb_name;
// check timers // check timers
if (not reordering_timer.is_valid()) { if (not reordering_timer.is_valid()) {
RlcError("Configuring RLC AM TX: timers not configured"); RlcError("Configuring RLC AM TX: timers not configured");

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

@ -24,6 +24,7 @@ rlc_tm::rlc_tm(srslog::basic_logger& logger,
rlc_common(logger), pdcp(pdcp_), rrc(rrc_), lcid(lcid_) rlc_common(logger), pdcp(pdcp_), rrc(rrc_), lcid(lcid_)
{ {
pool = byte_buffer_pool::get_instance(); pool = byte_buffer_pool::get_instance();
rb_name = "SRB0";
} }
// Warning: must call stop() to properly deallocate all buffers // Warning: must call stop() to properly deallocate all buffers
@ -80,12 +81,7 @@ void rlc_tm::write_sdu(unique_byte_buffer_t sdu)
uint32_t nof_bytes = sdu->N_bytes; uint32_t nof_bytes = sdu->N_bytes;
srsran::error_type<unique_byte_buffer_t> ret = ul_queue.try_write(std::move(sdu)); srsran::error_type<unique_byte_buffer_t> ret = ul_queue.try_write(std::move(sdu));
if (ret) { if (ret) {
RlcHexInfo(msg_ptr, RlcHexInfo(msg_ptr, nof_bytes, "Tx SDU, queue size=%d, bytes=%d", ul_queue.size(), ul_queue.size_bytes());
nof_bytes,
"%s Tx SDU, queue size=%d, bytes=%d",
rrc->get_rb_name(lcid),
ul_queue.size(),
ul_queue.size_bytes());
} else { } else {
RlcHexWarning(ret.error()->msg, RlcHexWarning(ret.error()->msg,
ret.error()->N_bytes, ret.error()->N_bytes,

133
lib/src/rlc/rlc_um_lte.cc
Unescape Escape View File

@ -50,8 +50,7 @@ bool rlc_um_lte::configure(const rlc_config_t& cnfg_)
return false; return false;
} }
logger.info("%s configured in %s: t_reordering=%d ms, rx_sn_field_length=%u bits, tx_sn_field_length=%u bits", RlcInfo("configured in %s - t_reordering=%d ms, rx_sn_field_length=%u bits, tx_sn_field_length=%u bits",
rb_name.c_str(),
srsran::to_string(cnfg_.rlc_mode), srsran::to_string(cnfg_.rlc_mode),
cfg.um.t_reordering, cfg.um.t_reordering,
srsran::to_number(cfg.um.rx_sn_field_length), srsran::to_number(cfg.um.rx_sn_field_length),
@ -102,7 +101,7 @@ bool rlc_um_lte::rlc_um_lte_tx::configure(const rlc_config_t& cnfg_, std::string
cfg = cnfg_; cfg = cnfg_;
if (cfg.um.tx_mod == 0) { if (cfg.um.tx_mod == 0) {
logger.error("Error configuring %s RLC UM: tx_mod==0", rb_name.c_str()); RlcError("Error configuring RLC UM - tx_mod==0");
return false; return false;
} }
@ -130,10 +129,7 @@ uint32_t rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uin
int pdu_space = SRSRAN_MIN(nof_bytes, pdu->get_tailroom()); int pdu_space = SRSRAN_MIN(nof_bytes, pdu->get_tailroom());
if (pdu_space <= head_len + 1) { if (pdu_space <= head_len + 1) {
logger.info("%s Cannot build a PDU - %d bytes available, %d bytes required for header", RlcInfo("Cannot build a PDU - %d bytes available, %d bytes required for header", nof_bytes, head_len);
rb_name.c_str(),
nof_bytes,
head_len);
return 0; return 0;
} }
@ -141,8 +137,7 @@ uint32_t rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uin
if (tx_sdu) { if (tx_sdu) {
uint32_t space = pdu_space - head_len; uint32_t space = pdu_space - head_len;
to_move = space >= tx_sdu->N_bytes ? tx_sdu->N_bytes : space; to_move = space >= tx_sdu->N_bytes ? tx_sdu->N_bytes : space;
logger.debug( RlcDebug("adding remainder of SDU segment - %d bytes of %d remaining", to_move, tx_sdu->N_bytes);
"%s adding remainder of SDU segment - %d bytes of %d remaining", rb_name.c_str(), to_move, tx_sdu->N_bytes);
memcpy(pdu_ptr, tx_sdu->msg, to_move); memcpy(pdu_ptr, tx_sdu->msg, to_move);
last_li = to_move; last_li = to_move;
pdu_ptr += to_move; pdu_ptr += to_move;
@ -153,12 +148,11 @@ uint32_t rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uin
#ifdef ENABLE_TIMESTAMP #ifdef ENABLE_TIMESTAMP
auto latency_us = tx_sdu->get_latency_us().count(); auto latency_us = tx_sdu->get_latency_us().count();
mean_pdu_latency_us.push(latency_us); mean_pdu_latency_us.push(latency_us);
logger.debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us", RlcDebug("Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us",
rb_name.c_str(),
(uint64_t)latency_us, (uint64_t)latency_us,
(long)mean_pdu_latency_us.value()); (long)mean_pdu_latency_us.value());
#else #else
logger.debug("%s Complete SDU scheduled for tx.", rb_name.c_str()); RlcDebug("%s Complete SDU scheduled for tx.", rb_name.c_str());
#endif #endif
tx_sdu.reset(); tx_sdu.reset();
} }
@ -168,7 +162,7 @@ uint32_t rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uin
// Pull SDUs from queue // Pull SDUs from queue
while (pdu_space > head_len + 1 && tx_sdu_queue.size() > 0) { while (pdu_space > head_len + 1 && tx_sdu_queue.size() > 0) {
logger.debug("pdu_space=%d, head_len=%d", pdu_space, head_len); RlcDebug("pdu_space=%d, head_len=%d", pdu_space, head_len);
if (last_li > 0) { if (last_li > 0) {
header.li[header.N_li++] = last_li; header.li[header.N_li++] = last_li;
} }
@ -181,7 +175,7 @@ uint32_t rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uin
} }
tx_sdu = tx_sdu_queue.read(); tx_sdu = tx_sdu_queue.read();
to_move = (space >= tx_sdu->N_bytes) ? tx_sdu->N_bytes : space; to_move = (space >= tx_sdu->N_bytes) ? tx_sdu->N_bytes : space;
logger.debug("%s adding new SDU segment - %d bytes of %d remaining", rb_name.c_str(), to_move, tx_sdu->N_bytes); RlcDebug("adding new SDU segment - %d bytes of %d remaining", to_move, tx_sdu->N_bytes);
memcpy(pdu_ptr, tx_sdu->msg, to_move); memcpy(pdu_ptr, tx_sdu->msg, to_move);
last_li = to_move; last_li = to_move;
pdu_ptr += to_move; pdu_ptr += to_move;
@ -192,12 +186,11 @@ uint32_t rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uin
#ifdef ENABLE_TIMESTAMP #ifdef ENABLE_TIMESTAMP
auto latency_us = tx_sdu->get_latency_us().count(); auto latency_us = tx_sdu->get_latency_us().count();
mean_pdu_latency_us.push(latency_us); mean_pdu_latency_us.push(latency_us);
logger.debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us", RlcDebug("Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us",
rb_name.c_str(),
(uint64_t)latency_us, (uint64_t)latency_us,
(long)mean_pdu_latency_us.value()); (long)mean_pdu_latency_us.value());
#else #else
logger.debug("%s Complete SDU scheduled for tx.", rb_name.c_str()); RlcDebug("Complete SDU scheduled for tx.");
#endif #endif
tx_sdu.reset(); tx_sdu.reset();
} }
@ -216,7 +209,7 @@ uint32_t rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uin
rlc_um_write_data_pdu_header(&header, pdu.get()); rlc_um_write_data_pdu_header(&header, pdu.get());
memcpy(payload, pdu->msg, pdu->N_bytes); memcpy(payload, pdu->msg, pdu->N_bytes);
logger.info(payload, pdu->N_bytes, "%s Tx PDU SN=%d (%d B)", rb_name.c_str(), header.sn, pdu->N_bytes); RlcHexInfo(payload, pdu->N_bytes, "Tx PDU SN=%d (%d B)", header.sn, pdu->N_bytes);
debug_state(); debug_state();
@ -225,7 +218,7 @@ uint32_t rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uin
void rlc_um_lte::rlc_um_lte_tx::debug_state() void rlc_um_lte::rlc_um_lte_tx::debug_state()
{ {
logger.debug("%s vt_us = %d", rb_name.c_str(), vt_us); RlcDebug("vt_us = %d", vt_us);
} }
void rlc_um_lte::rlc_um_lte_tx::reset() void rlc_um_lte::rlc_um_lte_tx::reset()
@ -247,14 +240,16 @@ bool rlc_um_lte::rlc_um_lte_rx::configure(const rlc_config_t& cnfg_, std::string
{ {
cfg = cnfg_; cfg = cnfg_;
rb_name = rb_name_;
if (cfg.um.rx_mod == 0) { if (cfg.um.rx_mod == 0) {
logger.error("Error configuring %s RLC UM: rx_mod==0", rb_name.c_str()); RlcError("Error configuring RLC UM: rx_mod==0");
return false; return false;
} }
// check timer // check timer
if (not reordering_timer.is_valid()) { if (not reordering_timer.is_valid()) {
logger.error("Configuring RLC UM RX: timers not configured"); RlcError("Configuring RLC UM RX: timers not configured");
return false; return false;
} }
@ -263,8 +258,6 @@ bool rlc_um_lte::rlc_um_lte_rx::configure(const rlc_config_t& cnfg_, std::string
reordering_timer.set(static_cast<uint32_t>(cfg.um.t_reordering), [this](uint32_t tid) { timer_expired(tid); }); reordering_timer.set(static_cast<uint32_t>(cfg.um.t_reordering), [this](uint32_t tid) { timer_expired(tid); });
} }
rb_name = rb_name_;
return true; return true;
} }
@ -303,17 +296,17 @@ void rlc_um_lte::rlc_um_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
{ {
rlc_umd_pdu_header_t header; rlc_umd_pdu_header_t header;
rlc_um_read_data_pdu_header(payload, nof_bytes, cfg.um.rx_sn_field_length, &header); rlc_um_read_data_pdu_header(payload, nof_bytes, cfg.um.rx_sn_field_length, &header);
logger.info(payload, nof_bytes, "%s Rx data PDU SN=%d (%d B)", rb_name.c_str(), header.sn, nof_bytes); RlcHexInfo(payload, nof_bytes, "Rx data PDU SN=%d (%d B)", header.sn, nof_bytes);
if (RX_MOD_BASE(header.sn) >= RX_MOD_BASE(vr_uh - cfg.um.rx_window_size) && if (RX_MOD_BASE(header.sn) >= RX_MOD_BASE(vr_uh - cfg.um.rx_window_size) &&
RX_MOD_BASE(header.sn) < RX_MOD_BASE(vr_ur)) { RX_MOD_BASE(header.sn) < RX_MOD_BASE(vr_ur)) {
logger.info("%s SN=%d outside rx window [%d:%d] - discarding", rb_name.c_str(), header.sn, vr_ur, vr_uh); RlcInfo("SN=%d outside rx window [%d:%d] - discarding", header.sn, vr_ur, vr_uh);
return; return;
} }
std::map<uint32_t, rlc_umd_pdu_t>::iterator it = rx_window.find(header.sn); std::map<uint32_t, rlc_umd_pdu_t>::iterator it = rx_window.find(header.sn);
if (rx_window.end() != it) { if (rx_window.end() != it) {
logger.info("%s Discarding duplicate SN=%d", rb_name.c_str(), header.sn); RlcInfo("Discarding duplicate SN=%d", header.sn);
return; return;
} }
@ -321,7 +314,7 @@ void rlc_um_lte::rlc_um_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
rlc_umd_pdu_t pdu = {}; rlc_umd_pdu_t pdu = {};
pdu.buf = make_byte_buffer(); pdu.buf = make_byte_buffer();
if (!pdu.buf) { if (!pdu.buf) {
logger.error("Discarting packet: no space in buffer pool"); RlcError("Discarding packet: no space in buffer pool");
return; return;
} }
memcpy(pdu.buf->msg, payload, nof_bytes); memcpy(pdu.buf->msg, payload, nof_bytes);
@ -339,9 +332,9 @@ void rlc_um_lte::rlc_um_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
} }
// Reassemble and deliver SDUs, while updating vr_ur // Reassemble and deliver SDUs, while updating vr_ur
logger.debug("Entering Reassemble from received PDU"); RlcDebug("Entering Reassemble from received PDU");
reassemble_rx_sdus(); reassemble_rx_sdus();
logger.debug("Finished reassemble from received PDU"); RlcDebug("Finished reassemble from received PDU");
// Update reordering variables and timers // Update reordering variables and timers
if (reordering_timer.is_running()) { if (reordering_timer.is_running()) {
@ -365,23 +358,23 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
if (!rx_sdu) { if (!rx_sdu) {
rx_sdu = make_byte_buffer(); rx_sdu = make_byte_buffer();
if (!rx_sdu) { if (!rx_sdu) {
logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus()."); RlcError("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().");
return; return;
} }
} }
// First catch up with lower edge of reordering window // First catch up with lower edge of reordering window
while (!inside_reordering_window(vr_ur)) { while (!inside_reordering_window(vr_ur)) {
logger.debug("SN=%d is not inside reordering windows", vr_ur); RlcDebug("SN=%d is not inside reordering windows", vr_ur);
if (rx_window.end() == rx_window.find(vr_ur)) { if (rx_window.end() == rx_window.find(vr_ur)) {
logger.debug("SN=%d not in rx_window. Reset received SDU", vr_ur); RlcDebug("SN=%d not in rx_window. Reset received SDU", vr_ur);
rx_sdu->clear(); rx_sdu->clear();
} else { } else {
// Handle any SDU segments // Handle any SDU segments
for (uint32_t i = 0; i < rx_window[vr_ur].header.N_li; i++) { for (uint32_t i = 0; i < rx_window[vr_ur].header.N_li; i++) {
int len = rx_window[vr_ur].header.li[i]; int len = rx_window[vr_ur].header.li[i];
logger.debug(rx_window[vr_ur].buf->msg, RlcHexDebug(rx_window[vr_ur].buf->msg,
len, len,
"Handling segment %d/%d of length %d B of SN=%d", "Handling segment %d/%d of length %d B of SN=%d",
i + 1, i + 1,
@ -390,7 +383,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
vr_ur); vr_ur);
// Check if we received a middle or end segment // Check if we received a middle or end segment
if (rx_sdu->N_bytes == 0 && i == 0 && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { if (rx_sdu->N_bytes == 0 && i == 0 && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) {
logger.warning("Dropping PDU %d in reassembly due to lost start segment", vr_ur); RlcWarning("Dropping PDU %d in reassembly due to lost start segment", vr_ur);
// Advance data pointers and continue with next segment // Advance data pointers and continue with next segment
rx_window[vr_ur].buf->msg += len; rx_window[vr_ur].buf->msg += len;
rx_window[vr_ur].buf->N_bytes -= len; rx_window[vr_ur].buf->N_bytes -= len;
@ -405,18 +398,13 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
rx_window[vr_ur].buf->N_bytes -= len; rx_window[vr_ur].buf->N_bytes -= len;
if ((pdu_lost && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) || if ((pdu_lost && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) ||
(vr_ur != ((vr_ur_in_rx_sdu + 1) % cfg.um.rx_mod))) { (vr_ur != ((vr_ur_in_rx_sdu + 1) % cfg.um.rx_mod))) {
logger.warning("Dropping remainder of lost PDU (lower edge middle segments, vr_ur=%d, vr_ur_in_rx_sdu=%d)", RlcWarning("Dropping remainder of lost PDU (lower edge middle segments, vr_ur=%d, vr_ur_in_rx_sdu=%d)",
vr_ur, vr_ur,
vr_ur_in_rx_sdu); vr_ur_in_rx_sdu);
rx_sdu->clear(); rx_sdu->clear();
metrics.num_lost_pdus++; metrics.num_lost_pdus++;
} else { } else {
logger.info(rx_sdu->msg, RlcHexInfo(rx_sdu->msg, rx_sdu->N_bytes, "Rx SDU vr_ur=%d, i=%d (lower edge middle segments)", vr_ur, i);
rx_sdu->N_bytes,
"%s Rx SDU vr_ur=%d, i=%d (lower edge middle segments)",
rb_name.c_str(),
vr_ur,
i);
rx_sdu->set_timestamp(); rx_sdu->set_timestamp();
metrics.num_rx_sdus++; metrics.num_rx_sdus++;
metrics.num_rx_sdu_bytes += rx_sdu->N_bytes; metrics.num_rx_sdu_bytes += rx_sdu->N_bytes;
@ -427,7 +415,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
} }
rx_sdu = make_byte_buffer(); rx_sdu = make_byte_buffer();
if (!rx_sdu) { if (!rx_sdu) {
logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus()."); RlcError("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().");
return; return;
} }
} }
@ -436,7 +424,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
// Handle last segment // Handle last segment
if (rx_sdu->N_bytes > 0 || rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { if (rx_sdu->N_bytes > 0 || rlc_um_start_aligned(rx_window[vr_ur].header.fi)) {
logger.info("Writing last segment in SDU buffer. Lower edge vr_ur=%d, Buffer size=%d, segment size=%d", RlcInfo("Writing last segment in SDU buffer. Lower edge vr_ur=%d, Buffer size=%d, segment size=%d",
vr_ur, vr_ur,
rx_sdu->N_bytes, rx_sdu->N_bytes,
rx_window[vr_ur].buf->N_bytes); rx_window[vr_ur].buf->N_bytes);
@ -446,12 +434,11 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
vr_ur_in_rx_sdu = vr_ur; vr_ur_in_rx_sdu = vr_ur;
if (rlc_um_end_aligned(rx_window[vr_ur].header.fi)) { if (rlc_um_end_aligned(rx_window[vr_ur].header.fi)) {
if (pdu_lost && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { if (pdu_lost && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) {
logger.warning("Dropping remainder of lost PDU (lower edge last segments)"); RlcWarning("Dropping remainder of lost PDU (lower edge last segments)");
rx_sdu->clear(); rx_sdu->clear();
metrics.num_lost_pdus++; metrics.num_lost_pdus++;
} else { } else {
logger.info( RlcHexInfo(rx_sdu->msg, rx_sdu->N_bytes, "Rx SDU vr_ur=%d (lower edge last segments)", vr_ur);
rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU vr_ur=%d (lower edge last segments)", rb_name.c_str(), vr_ur);
rx_sdu->set_timestamp(); rx_sdu->set_timestamp();
metrics.num_rx_sdus++; metrics.num_rx_sdus++;
metrics.num_rx_sdu_bytes += rx_sdu->N_bytes; metrics.num_rx_sdu_bytes += rx_sdu->N_bytes;
@ -462,7 +449,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
} }
rx_sdu = make_byte_buffer(); rx_sdu = make_byte_buffer();
if (!rx_sdu) { if (!rx_sdu) {
logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus()."); RlcError("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().");
return; return;
} }
} }
@ -479,10 +466,10 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
// Now update vr_ur until we reach an SN we haven't yet received // Now update vr_ur until we reach an SN we haven't yet received
while (rx_window.end() != rx_window.find(vr_ur)) { while (rx_window.end() != rx_window.find(vr_ur)) {
logger.debug("Reassemble loop for vr_ur=%d", vr_ur); RlcDebug("Reassemble loop for vr_ur=%d", vr_ur);
if (not pdu_belongs_to_rx_sdu()) { if (not pdu_belongs_to_rx_sdu()) {
logger.info("PDU SN=%d lost, stop reassambling SDU (vr_ur_in_rx_sdu=%d)", vr_ur_in_rx_sdu + 1, vr_ur_in_rx_sdu); RlcInfo("PDU SN=%d lost, stop reassambling SDU (vr_ur_in_rx_sdu=%d)", vr_ur_in_rx_sdu + 1, vr_ur_in_rx_sdu);
pdu_lost = false; // Reset flag to not prevent reassembling of further segments pdu_lost = false; // Reset flag to not prevent reassembling of further segments
rx_sdu->clear(); rx_sdu->clear();
} }
@ -490,7 +477,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
// Handle any SDU segments // Handle any SDU segments
for (uint32_t i = 0; i < rx_window[vr_ur].header.N_li; i++) { for (uint32_t i = 0; i < rx_window[vr_ur].header.N_li; i++) {
uint16_t len = rx_window[vr_ur].header.li[i]; uint16_t len = rx_window[vr_ur].header.li[i];
logger.debug("Handling SDU segment i=%d with len=%d of vr_ur=%d N_li=%d [%s]", RlcDebug("Handling SDU segment i=%d with len=%d of vr_ur=%d N_li=%d [%s]",
i, i,
len, len,
vr_ur, vr_ur,
@ -498,11 +485,11 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
rlc_fi_field_text[rx_window[vr_ur].header.fi]); rlc_fi_field_text[rx_window[vr_ur].header.fi]);
// Check if the first part of the PDU is a middle or end segment // Check if the first part of the PDU is a middle or end segment
if (rx_sdu->N_bytes == 0 && i == 0 && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { if (rx_sdu->N_bytes == 0 && i == 0 && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) {
logger.info( RlcHexInfo(
rx_window[vr_ur].buf->msg, len, "Dropping first %d B of SN=%d due to lost start segment", len, vr_ur); rx_window[vr_ur].buf->msg, len, "Dropping first %d B of SN=%d due to lost start segment", len, vr_ur);
if (rx_window[vr_ur].buf->N_bytes < len) { if (rx_window[vr_ur].buf->N_bytes < len) {
logger.error("Dropping remaining remainder of SN=%d too (N_bytes=%u < len=%d)", RlcError("Dropping remaining remainder of SN=%d too (N_bytes=%u < len=%d)",
vr_ur, vr_ur,
rx_window[vr_ur].buf->N_bytes, rx_window[vr_ur].buf->N_bytes,
len); len);
@ -522,7 +509,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
// Check available space in SDU // Check available space in SDU
if ((uint32_t)len > rx_sdu->get_tailroom()) { if ((uint32_t)len > rx_sdu->get_tailroom()) {
logger.error("Dropping PDU %d due to buffer mis-alignment (current segment len %d B, received %d B)", RlcError("Dropping PDU %d due to buffer mis-alignment (current segment len %d B, received %d B)",
vr_ur, vr_ur,
rx_sdu->N_bytes, rx_sdu->N_bytes,
len); len);
@ -532,11 +519,11 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
} }
if (not pdu_belongs_to_rx_sdu()) { if (not pdu_belongs_to_rx_sdu()) {
logger.info(rx_window[vr_ur].buf->msg, len, "Copying first %d bytes of new SDU", len); RlcHexInfo(rx_window[vr_ur].buf->msg, len, "Copying first %d bytes of new SDU", len);
logger.info("Updating vr_ur_in_rx_sdu. old=%d, new=%d", vr_ur_in_rx_sdu, vr_ur); RlcInfo("Updating vr_ur_in_rx_sdu. old=%d, new=%d", vr_ur_in_rx_sdu, vr_ur);
vr_ur_in_rx_sdu = vr_ur; vr_ur_in_rx_sdu = vr_ur;
} else { } else {
logger.info(rx_window[vr_ur].buf->msg, RlcHexInfo(rx_window[vr_ur].buf->msg,
len, len,
"Concatenating %d bytes in to current length %d. rx_window remaining bytes=%d, " "Concatenating %d bytes in to current length %d. rx_window remaining bytes=%d, "
"vr_ur_in_rx_sdu=%d, vr_ur=%d, rx_mod=%d, last_mod=%d", "vr_ur_in_rx_sdu=%d, vr_ur=%d, rx_mod=%d, last_mod=%d",
@ -556,12 +543,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
vr_ur_in_rx_sdu = vr_ur; vr_ur_in_rx_sdu = vr_ur;
if (pdu_belongs_to_rx_sdu()) { if (pdu_belongs_to_rx_sdu()) {
logger.info(rx_sdu->msg, RlcHexInfo(rx_sdu->msg, rx_sdu->N_bytes, "Rx SDU vr_ur=%d, i=%d, (update vr_ur middle segments)", vr_ur, i);
rx_sdu->N_bytes,
"%s Rx SDU vr_ur=%d, i=%d, (update vr_ur middle segments)",
rb_name.c_str(),
vr_ur,
i);
rx_sdu->set_timestamp(); rx_sdu->set_timestamp();
metrics.num_rx_sdus++; metrics.num_rx_sdus++;
metrics.num_rx_sdu_bytes += rx_sdu->N_bytes; metrics.num_rx_sdu_bytes += rx_sdu->N_bytes;
@ -572,11 +554,11 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
} }
rx_sdu = make_byte_buffer(); rx_sdu = make_byte_buffer();
if (!rx_sdu) { if (!rx_sdu) {
logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus()."); RlcError("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().");
return; return;
} }
} else { } else {
logger.warning("Dropping remainder of lost PDU (update vr_ur middle segments, vr_ur=%d, vr_ur_in_rx_sdu=%d)", RlcWarning("Dropping remainder of lost PDU (update vr_ur middle segments, vr_ur=%d, vr_ur_in_rx_sdu=%d)",
vr_ur, vr_ur,
vr_ur_in_rx_sdu); vr_ur_in_rx_sdu);
// Advance data pointers and continue with next segment // Advance data pointers and continue with next segment
@ -590,7 +572,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
// Handle last segment // Handle last segment
if (rx_sdu->N_bytes == 0 && rx_window[vr_ur].header.N_li == 0 && if (rx_sdu->N_bytes == 0 && rx_window[vr_ur].header.N_li == 0 &&
!rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) {
logger.warning("Dropping PDU %d during last segment handling due to lost start segment", vr_ur); RlcWarning("Dropping PDU %d during last segment handling due to lost start segment", vr_ur);
rx_sdu->clear(); rx_sdu->clear();
metrics.num_lost_pdus++; metrics.num_lost_pdus++;
goto clean_up_rx_window; goto clean_up_rx_window;
@ -599,7 +581,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
if (rx_sdu->N_bytes < SRSRAN_MAX_BUFFER_SIZE_BYTES && if (rx_sdu->N_bytes < SRSRAN_MAX_BUFFER_SIZE_BYTES &&
rx_window[vr_ur].buf->N_bytes < SRSRAN_MAX_BUFFER_SIZE_BYTES && rx_window[vr_ur].buf->N_bytes < SRSRAN_MAX_BUFFER_SIZE_BYTES &&
rx_window[vr_ur].buf->N_bytes + rx_sdu->N_bytes < SRSRAN_MAX_BUFFER_SIZE_BYTES) { rx_window[vr_ur].buf->N_bytes + rx_sdu->N_bytes < SRSRAN_MAX_BUFFER_SIZE_BYTES) {
logger.info(rx_window[vr_ur].buf->msg, RlcHexInfo(rx_window[vr_ur].buf->msg,
rx_window[vr_ur].buf->N_bytes, rx_window[vr_ur].buf->N_bytes,
"Writing last segment in SDU buffer. Updating vr_ur=%d, vr_ur_in_rx_sdu=%d, Buffer size=%d, " "Writing last segment in SDU buffer. Updating vr_ur=%d, vr_ur_in_rx_sdu=%d, Buffer size=%d, "
"segment size=%d", "segment size=%d",
@ -610,7 +592,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
memcpy(&rx_sdu->msg[rx_sdu->N_bytes], rx_window[vr_ur].buf->msg, rx_window[vr_ur].buf->N_bytes); memcpy(&rx_sdu->msg[rx_sdu->N_bytes], rx_window[vr_ur].buf->msg, rx_window[vr_ur].buf->N_bytes);
rx_sdu->N_bytes += rx_window[vr_ur].buf->N_bytes; rx_sdu->N_bytes += rx_window[vr_ur].buf->N_bytes;
} else { } else {
logger.error("Out of bounds while reassembling SDU buffer in UM: sdu_len=%d, window_buffer_len=%d, vr_ur=%d", RlcError("Out of bounds while reassembling SDU buffer in UM: sdu_len=%d, window_buffer_len=%d, vr_ur=%d",
rx_sdu->N_bytes, rx_sdu->N_bytes,
rx_window[vr_ur].buf->N_bytes, rx_window[vr_ur].buf->N_bytes,
vr_ur); vr_ur);
@ -618,12 +600,11 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
vr_ur_in_rx_sdu = vr_ur; vr_ur_in_rx_sdu = vr_ur;
if (rlc_um_end_aligned(rx_window[vr_ur].header.fi)) { if (rlc_um_end_aligned(rx_window[vr_ur].header.fi)) {
if (pdu_lost && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) { if (pdu_lost && !rlc_um_start_aligned(rx_window[vr_ur].header.fi)) {
logger.warning("Dropping remainder of lost PDU (update vr_ur last segments)"); RlcWarning("Dropping remainder of lost PDU (update vr_ur last segments)");
rx_sdu->clear(); rx_sdu->clear();
metrics.num_lost_pdus++; metrics.num_lost_pdus++;
} else { } else {
logger.info( RlcHexInfo(rx_sdu->msg, rx_sdu->N_bytes, "Rx SDU vr_ur=%d (update vr_ur last segments)", vr_ur);
rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU vr_ur=%d (update vr_ur last segments)", rb_name.c_str(), vr_ur);
rx_sdu->set_timestamp(); rx_sdu->set_timestamp();
metrics.num_rx_sdus++; metrics.num_rx_sdus++;
metrics.num_rx_sdu_bytes += rx_sdu->N_bytes; metrics.num_rx_sdu_bytes += rx_sdu->N_bytes;
@ -634,7 +615,7 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
} }
rx_sdu = make_byte_buffer(); rx_sdu = make_byte_buffer();
if (!rx_sdu) { if (!rx_sdu) {
logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus()."); RlcError("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().");
return; return;
} }
} }
@ -681,9 +662,9 @@ void rlc_um_lte::rlc_um_lte_rx::timer_expired(uint32_t timeout_id)
{ {
if (reordering_timer.id() == timeout_id) { if (reordering_timer.id() == timeout_id) {
// 36.322 v10 Section 5.1.2.2.4 // 36.322 v10 Section 5.1.2.2.4
logger.info("%s reordering timeout expiry - updating vr_ur and reassembling", rb_name.c_str()); RlcInfo("%s reordering timeout expiry - updating vr_ur and reassembling", rb_name.c_str());
logger.warning("Lost PDU SN=%d", vr_ur); RlcWarning("Lost PDU SN=%d", vr_ur);
pdu_lost = true; pdu_lost = true;
if (rx_sdu != NULL) { if (rx_sdu != NULL) {
@ -692,9 +673,9 @@ void rlc_um_lte::rlc_um_lte_rx::timer_expired(uint32_t timeout_id)
while (RX_MOD_BASE(vr_ur) < RX_MOD_BASE(vr_ux)) { while (RX_MOD_BASE(vr_ur) < RX_MOD_BASE(vr_ux)) {
vr_ur = (vr_ur + 1) % cfg.um.rx_mod; vr_ur = (vr_ur + 1) % cfg.um.rx_mod;
logger.debug("Entering Reassemble from timeout id=%d", timeout_id); RlcDebug("Entering Reassemble from timeout id=%d", timeout_id);
reassemble_rx_sdus(); reassemble_rx_sdus();
logger.debug("Finished reassemble from timeout id=%d", timeout_id); RlcDebug("Finished reassemble from timeout id=%d", timeout_id);
} }
if (RX_MOD_BASE(vr_uh) > RX_MOD_BASE(vr_ur)) { if (RX_MOD_BASE(vr_uh) > RX_MOD_BASE(vr_ur)) {
@ -712,7 +693,7 @@ void rlc_um_lte::rlc_um_lte_rx::timer_expired(uint32_t timeout_id)
void rlc_um_lte::rlc_um_lte_rx::debug_state() void rlc_um_lte::rlc_um_lte_rx::debug_state()
{ {
logger.debug("%s vr_ur = %d, vr_ux = %d, vr_uh = %d", rb_name.c_str(), vr_ur, vr_ux, vr_uh); RlcDebug("vr_ur = %d, vr_ux = %d, vr_uh = %d", vr_ur, vr_ux, vr_uh);
} }
/**************************************************************************** /****************************************************************************

Write Preview
Loading…
Cancel
Save