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

Ported the RLC classes to srslog in the lib dir.

Browse Source
master
faluco 4 years ago committed by faluco
parent f424f2e113
commit 57f66febfc
23 changed files with 702 additions and 667 deletions
Show Stats Download Patch File Download Diff File

2
lib/include/srslte/upper/rlc.h
Unescape Escape View File

@ -86,7 +86,7 @@ private:
void reset_metrics(); void reset_metrics();
byte_buffer_pool* pool = nullptr; byte_buffer_pool* pool = nullptr;
srslte::log_ref rlc_log; srslog::basic_logger& logger;
srsue::pdcp_interface_rlc* pdcp = nullptr; srsue::pdcp_interface_rlc* pdcp = nullptr;
srsue::rrc_interface_rlc* rrc = nullptr; srsue::rrc_interface_rlc* rrc = nullptr;
srslte::timer_handler* timers = nullptr; srslte::timer_handler* timers = nullptr;

8
lib/include/srslte/upper/rlc_am_lte.h
Unescape Escape View File

@ -69,7 +69,7 @@ struct pdcp_sdu_info_t {
class rlc_am_lte : public rlc_common class rlc_am_lte : public rlc_common
{ {
public: public:
rlc_am_lte(srslte::log_ref log_, rlc_am_lte(srslog::basic_logger& logger,
uint32_t lcid_, uint32_t lcid_,
srsue::pdcp_interface_rlc* pdcp_, srsue::pdcp_interface_rlc* pdcp_,
srsue::rrc_interface_rlc* rrc_, srsue::rrc_interface_rlc* rrc_,
@ -148,7 +148,7 @@ private:
rlc_am_lte* parent = nullptr; rlc_am_lte* parent = nullptr;
byte_buffer_pool* pool = nullptr; byte_buffer_pool* pool = nullptr;
srslte::log_ref log; srslog::basic_logger& logger;
/**************************************************************************** /****************************************************************************
* Configurable parameters * Configurable parameters
@ -239,7 +239,7 @@ private:
rlc_am_lte* parent = nullptr; rlc_am_lte* parent = nullptr;
byte_buffer_pool* pool = nullptr; byte_buffer_pool* pool = nullptr;
srslte::log_ref log; srslog::basic_logger& logger;
/**************************************************************************** /****************************************************************************
* Configurable parameters * Configurable parameters
@ -284,7 +284,7 @@ private:
// Common variables needed/provided by parent class // Common variables needed/provided by parent class
srsue::rrc_interface_rlc* rrc = nullptr; srsue::rrc_interface_rlc* rrc = nullptr;
srslte::log_ref log; srslog::basic_logger& logger;
srsue::pdcp_interface_rlc* pdcp = nullptr; srsue::pdcp_interface_rlc* pdcp = nullptr;
srslte::timer_handler* timers = nullptr; srslte::timer_handler* timers = nullptr;
uint32_t lcid = 0; uint32_t lcid = 0;

4
lib/include/srslte/upper/rlc_common.h
Unescape Escape View File

@ -282,7 +282,7 @@ private:
// Do not block ever // Do not block ever
if (!rx_pdu_resume_queue.try_push(p)) { if (!rx_pdu_resume_queue.try_push(p)) {
srslte::logmap::get("RLC ")->warning("Dropping SDUs while bearer suspended.\n"); srslog::fetch_basic_logger("RLC").warning("Dropping SDUs while bearer suspended.");
return; return;
} }
} }
@ -292,7 +292,7 @@ private:
{ {
// Do not block ever // Do not block ever
if (not tx_sdu_resume_queue.try_push(std::move(sdu))) { if (not tx_sdu_resume_queue.try_push(std::move(sdu))) {
srslte::logmap::get("RLC ")->warning("Dropping SDUs while bearer suspended.\n"); srslog::fetch_basic_logger("RLC").warning("Dropping SDUs while bearer suspended.");
return; return;
} }
} }

7
lib/include/srslte/upper/rlc_tm.h
Unescape Escape View File

@ -25,7 +25,10 @@ namespace srslte {
class rlc_tm final : public rlc_common class rlc_tm final : public rlc_common
{ {
public: public:
rlc_tm(srslte::log_ref log_, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_); rlc_tm(srslog::basic_logger& logger,
uint32_t lcid_,
srsue::pdcp_interface_rlc* pdcp_,
srsue::rrc_interface_rlc* rrc_);
~rlc_tm() override; ~rlc_tm() override;
bool configure(const rlc_config_t& cnfg) override; bool configure(const rlc_config_t& cnfg) override;
void stop() override; void stop() override;
@ -53,7 +56,7 @@ public:
private: private:
byte_buffer_pool* pool = nullptr; byte_buffer_pool* pool = nullptr;
srslte::log_ref log; srslog::basic_logger& logger;
uint32_t lcid = 0; uint32_t lcid = 0;
srsue::pdcp_interface_rlc* pdcp = nullptr; srsue::pdcp_interface_rlc* pdcp = nullptr;
srsue::rrc_interface_rlc* rrc = nullptr; srsue::rrc_interface_rlc* rrc = nullptr;

9
lib/include/srslte/upper/rlc_um_base.h
Unescape Escape View File

@ -30,7 +30,7 @@ namespace srslte {
class rlc_um_base : public rlc_common class rlc_um_base : public rlc_common
{ {
public: public:
rlc_um_base(srslte::log_ref log_, rlc_um_base(srslog::basic_logger& logger,
uint32_t lcid_, uint32_t lcid_,
srsue::pdcp_interface_rlc* pdcp_, srsue::pdcp_interface_rlc* pdcp_,
srsue::rrc_interface_rlc* rrc_, srsue::rrc_interface_rlc* rrc_,
@ -83,7 +83,7 @@ protected:
protected: protected:
byte_buffer_pool* pool = nullptr; byte_buffer_pool* pool = nullptr;
srslte::log_ref log; srslog::basic_logger& logger;
std::string rb_name; std::string rb_name;
rlc_um_base* parent = nullptr; rlc_um_base* parent = nullptr;
@ -111,7 +111,6 @@ protected:
// Receiver sub-class base // Receiver sub-class base
class rlc_um_base_rx : public timer_callback class rlc_um_base_rx : public timer_callback
{ {
public: public:
rlc_um_base_rx(rlc_um_base* parent_); rlc_um_base_rx(rlc_um_base* parent_);
virtual ~rlc_um_base_rx(); virtual ~rlc_um_base_rx();
@ -124,7 +123,7 @@ protected:
protected: protected:
byte_buffer_pool* pool = nullptr; byte_buffer_pool* pool = nullptr;
srslte::log_ref log; srslog::basic_logger& logger;
srslte::timer_handler* timers = nullptr; srslte::timer_handler* timers = nullptr;
srsue::pdcp_interface_rlc* pdcp = nullptr; srsue::pdcp_interface_rlc* pdcp = nullptr;
srsue::rrc_interface_rlc* rrc = nullptr; srsue::rrc_interface_rlc* rrc = nullptr;
@ -145,7 +144,7 @@ protected:
// Common variables needed by parent class // Common variables needed by parent class
srsue::rrc_interface_rlc* rrc = nullptr; srsue::rrc_interface_rlc* rrc = nullptr;
srsue::pdcp_interface_rlc* pdcp = nullptr; srsue::pdcp_interface_rlc* pdcp = nullptr;
srslte::log_ref log; srslog::basic_logger& logger;
srslte::timer_handler* timers = nullptr; srslte::timer_handler* timers = nullptr;
uint32_t lcid = 0; uint32_t lcid = 0;
rlc_config_t cfg = {}; rlc_config_t cfg = {};

2
lib/include/srslte/upper/rlc_um_lte.h
Unescape Escape View File

@ -34,7 +34,7 @@ typedef struct {
class rlc_um_lte : public rlc_um_base class rlc_um_lte : public rlc_um_base
{ {
public: public:
rlc_um_lte(srslte::log_ref log_, rlc_um_lte(srslog::basic_logger& logger,
uint32_t lcid_, uint32_t lcid_,
srsue::pdcp_interface_rlc* pdcp_, srsue::pdcp_interface_rlc* pdcp_,
srsue::rrc_interface_rlc* rrc_, srsue::rrc_interface_rlc* rrc_,

2
lib/include/srslte/upper/rlc_um_nr.h
Unescape Escape View File

@ -34,7 +34,7 @@ typedef struct {
class rlc_um_nr : public rlc_um_base class rlc_um_nr : public rlc_um_base
{ {
public: public:
rlc_um_nr(srslte::log_ref log_, rlc_um_nr(srslog::basic_logger& logger,
uint32_t lcid_, uint32_t lcid_,
srsue::pdcp_interface_rlc* pdcp_, srsue::pdcp_interface_rlc* pdcp_,
srsue::rrc_interface_rlc* rrc_, srsue::rrc_interface_rlc* rrc_,

106
lib/src/upper/rlc.cc
Unescape Escape View File

@ -19,7 +19,7 @@
namespace srslte { namespace srslte {
rlc::rlc(const char* logname) : rlc_log(logname) rlc::rlc(const char* logname) : logger(srslog::fetch_basic_logger(logname))
{ {
pool = byte_buffer_pool::get_instance(); pool = byte_buffer_pool::get_instance();
pthread_rwlock_init(&rwlock, NULL); pthread_rwlock_init(&rwlock, NULL);
@ -109,7 +109,7 @@ void rlc::get_metrics(rlc_metrics_t& m, const uint32_t nof_tti)
double rx_rate_mbps = (nof_tti > 0) ? ((metrics.num_rx_pdu_bytes * 8 / (double)1e6) / (nof_tti / 1000.0)) : 0.0; double rx_rate_mbps = (nof_tti > 0) ? ((metrics.num_rx_pdu_bytes * 8 / (double)1e6) / (nof_tti / 1000.0)) : 0.0;
double tx_rate_mbps = (nof_tti > 0) ? ((metrics.num_tx_pdu_bytes * 8 / (double)1e6) / (nof_tti / 1000.0)) : 0.0; double tx_rate_mbps = (nof_tti > 0) ? ((metrics.num_tx_pdu_bytes * 8 / (double)1e6) / (nof_tti / 1000.0)) : 0.0;
rlc_log->info("lcid=%d, rx_rate_mbps=%4.2f (real=%4.2f), tx_rate_mbps=%4.2f (real=%4.2f)\n", logger.info("lcid=%d, rx_rate_mbps=%4.2f (real=%4.2f), tx_rate_mbps=%4.2f (real=%4.2f)",
it->first, it->first,
rx_rate_mbps, rx_rate_mbps,
rx_rate_mbps_real_time, rx_rate_mbps_real_time,
@ -121,7 +121,7 @@ void rlc::get_metrics(rlc_metrics_t& m, const uint32_t nof_tti)
// Add multicast metrics // Add multicast metrics
for (rlc_map_t::iterator it = rlc_array_mrb.begin(); it != rlc_array_mrb.end(); ++it) { for (rlc_map_t::iterator it = rlc_array_mrb.begin(); it != rlc_array_mrb.end(); ++it) {
rlc_bearer_metrics_t metrics = it->second->get_metrics(); rlc_bearer_metrics_t metrics = it->second->get_metrics();
rlc_log->info("MCH_LCID=%d, rx_rate_mbps=%4.2f\n", logger.info("MCH_LCID=%d, rx_rate_mbps=%4.2f",
it->first, it->first,
(metrics.num_rx_pdu_bytes * 8 / static_cast<double>(1e6)) / secs.count()); (metrics.num_rx_pdu_bytes * 8 / static_cast<double>(1e6)) / secs.count());
m.bearer[it->first] = metrics; m.bearer[it->first] = metrics;
@ -148,10 +148,10 @@ void rlc::reestablish()
void rlc::reestablish(uint32_t lcid) void rlc::reestablish(uint32_t lcid)
{ {
if (valid_lcid(lcid)) { if (valid_lcid(lcid)) {
rlc_log->info("Reestablishing %s\n", rrc->get_rb_name(lcid).c_str()); logger.info("Reestablishing %s", rrc->get_rb_name(lcid).c_str());
rlc_array.at(lcid)->reestablish(); rlc_array.at(lcid)->reestablish();
} else { } else {
rlc_log->warning("RLC LCID %d doesn't exist.\n", lcid); logger.warning("RLC LCID %d doesn't exist.", lcid);
} }
} }
@ -191,7 +191,7 @@ void rlc::write_sdu(uint32_t lcid, unique_byte_buffer_t sdu)
{ {
// TODO: rework build PDU logic to allow large SDUs (without concatenation) // TODO: rework build PDU logic to allow large SDUs (without concatenation)
if (sdu->N_bytes > RLC_MAX_SDU_SIZE) { if (sdu->N_bytes > RLC_MAX_SDU_SIZE) {
rlc_log->warning("Dropping too long SDU of size %d B (Max. size %d B).\n", sdu->N_bytes, RLC_MAX_SDU_SIZE); logger.warning("Dropping too long SDU of size %d B (Max. size %d B).", sdu->N_bytes, RLC_MAX_SDU_SIZE);
return; return;
} }
@ -199,7 +199,7 @@ void rlc::write_sdu(uint32_t lcid, unique_byte_buffer_t sdu)
rlc_array.at(lcid)->write_sdu_s(std::move(sdu)); rlc_array.at(lcid)->write_sdu_s(std::move(sdu));
update_bsr(lcid); update_bsr(lcid);
} else { } else {
rlc_log->warning("RLC LCID %d doesn't exist. Deallocating SDU\n", lcid); logger.warning("RLC LCID %d doesn't exist. Deallocating SDU", lcid);
} }
} }
@ -209,7 +209,7 @@ void rlc::write_sdu_mch(uint32_t lcid, unique_byte_buffer_t sdu)
rlc_array_mrb.at(lcid)->write_sdu(std::move(sdu)); rlc_array_mrb.at(lcid)->write_sdu(std::move(sdu));
update_bsr_mch(lcid); update_bsr_mch(lcid);
} else { } else {
rlc_log->warning("RLC LCID %d doesn't exist. Deallocating SDU\n", lcid); logger.warning("RLC LCID %d doesn't exist. Deallocating SDU", lcid);
} }
} }
@ -220,7 +220,7 @@ bool rlc::rb_is_um(uint32_t lcid)
if (valid_lcid(lcid)) { if (valid_lcid(lcid)) {
ret = rlc_array.at(lcid)->get_mode() == rlc_mode_t::um; ret = rlc_array.at(lcid)->get_mode() == rlc_mode_t::um;
} else { } else {
rlc_log->warning("LCID %d doesn't exist.\n", lcid); logger.warning("LCID %d doesn't exist.", lcid);
} }
return ret; return ret;
@ -232,7 +232,7 @@ void rlc::discard_sdu(uint32_t lcid, uint32_t discard_sn)
rlc_array.at(lcid)->discard_sdu(discard_sn); rlc_array.at(lcid)->discard_sdu(discard_sn);
update_bsr(lcid); update_bsr(lcid);
} else { } else {
rlc_log->warning("RLC LCID %d doesn't exist. Ignoring discard SDU\n", lcid); logger.warning("RLC LCID %d doesn't exist. Ignoring discard SDU", lcid);
} }
} }
@ -241,7 +241,7 @@ bool rlc::sdu_queue_is_full(uint32_t lcid)
if (valid_lcid(lcid)) { if (valid_lcid(lcid)) {
return rlc_array.at(lcid)->sdu_queue_is_full(); return rlc_array.at(lcid)->sdu_queue_is_full();
} }
rlc_log->warning("RLC LCID %d doesn't exist. Ignoring queue check\n", lcid); logger.warning("RLC LCID %d doesn't exist. Ignoring queue check", lcid);
return false; return false;
} }
@ -291,7 +291,7 @@ int rlc::read_pdu(uint32_t lcid, uint8_t* payload, uint32_t nof_bytes)
ret = rlc_array.at(lcid)->read_pdu(payload, nof_bytes); ret = rlc_array.at(lcid)->read_pdu(payload, nof_bytes);
update_bsr(lcid); update_bsr(lcid);
} else { } else {
rlc_log->warning("LCID %d doesn't exist.\n", lcid); logger.warning("LCID %d doesn't exist.", lcid);
} }
return ret; return ret;
@ -306,7 +306,7 @@ int rlc::read_pdu_mch(uint32_t lcid, uint8_t* payload, uint32_t nof_bytes)
ret = rlc_array_mrb.at(lcid)->read_pdu(payload, nof_bytes); ret = rlc_array_mrb.at(lcid)->read_pdu(payload, nof_bytes);
update_bsr_mch(lcid); update_bsr_mch(lcid);
} else { } else {
rlc_log->warning("LCID %d doesn't exist.\n", lcid); logger.warning("LCID %d doesn't exist.", lcid);
} }
return ret; return ret;
@ -319,21 +319,21 @@ void rlc::write_pdu(uint32_t lcid, uint8_t* payload, uint32_t nof_bytes)
rlc_array.at(lcid)->write_pdu_s(payload, nof_bytes); rlc_array.at(lcid)->write_pdu_s(payload, nof_bytes);
update_bsr(lcid); update_bsr(lcid);
} else { } else {
rlc_log->warning("LCID %d doesn't exist. Dropping PDU.\n", lcid); logger.warning("LCID %d doesn't exist. Dropping PDU.", lcid);
} }
} }
// Pass directly to PDCP, no DL througput counting done // Pass directly to PDCP, no DL througput counting done
void rlc::write_pdu_bcch_bch(srslte::unique_byte_buffer_t pdu) void rlc::write_pdu_bcch_bch(srslte::unique_byte_buffer_t pdu)
{ {
rlc_log->info_hex(pdu->msg, pdu->N_bytes, "BCCH BCH message received."); logger.info(pdu->msg, pdu->N_bytes, "BCCH BCH message received.");
pdcp->write_pdu_bcch_bch(std::move(pdu)); pdcp->write_pdu_bcch_bch(std::move(pdu));
} }
// Pass directly to PDCP, no DL througput counting done // Pass directly to PDCP, no DL througput counting done
void rlc::write_pdu_bcch_dlsch(uint8_t* payload, uint32_t nof_bytes) void rlc::write_pdu_bcch_dlsch(uint8_t* payload, uint32_t nof_bytes)
{ {
rlc_log->info_hex(payload, nof_bytes, "BCCH TXSCH message received."); logger.info(payload, nof_bytes, "BCCH TXSCH message received.");
unique_byte_buffer_t buf = make_byte_buffer(); unique_byte_buffer_t buf = make_byte_buffer();
if (buf != NULL) { if (buf != NULL) {
memcpy(buf->msg, payload, nof_bytes); memcpy(buf->msg, payload, nof_bytes);
@ -341,14 +341,14 @@ void rlc::write_pdu_bcch_dlsch(uint8_t* payload, uint32_t nof_bytes)
buf->set_timestamp(); buf->set_timestamp();
pdcp->write_pdu_bcch_dlsch(std::move(buf)); pdcp->write_pdu_bcch_dlsch(std::move(buf));
} else { } else {
rlc_log->error("Fatal error: Out of buffers from the pool in write_pdu_bcch_dlsch()\n"); logger.error("Fatal error: Out of buffers from the pool in write_pdu_bcch_dlsch()");
} }
} }
// Pass directly to PDCP, no DL througput counting done // Pass directly to PDCP, no DL througput counting done
void rlc::write_pdu_pcch(srslte::unique_byte_buffer_t pdu) void rlc::write_pdu_pcch(srslte::unique_byte_buffer_t pdu)
{ {
rlc_log->info_hex(pdu->msg, pdu->N_bytes, "PCCH message received."); logger.info(pdu->msg, pdu->N_bytes, "PCCH message received.");
pdcp->write_pdu_pcch(std::move(pdu)); pdcp->write_pdu_pcch(std::move(pdu));
} }
@ -393,7 +393,7 @@ void rlc::add_bearer(uint32_t lcid, const rlc_config_t& cnfg)
if (cnfg.rlc_mode != rlc_mode_t::tm and rlc_array.find(lcid) != rlc_array.end()) { if (cnfg.rlc_mode != rlc_mode_t::tm and rlc_array.find(lcid) != rlc_array.end()) {
if (rlc_array[lcid]->get_mode() != cnfg.rlc_mode) { if (rlc_array[lcid]->get_mode() != cnfg.rlc_mode) {
rlc_log->info("Switching RLC entity type. Recreating it.\n"); logger.info("Switching RLC entity type. Recreating it.");
rlc_array.erase(lcid); rlc_array.erase(lcid);
} }
} }
@ -402,16 +402,16 @@ void rlc::add_bearer(uint32_t lcid, const rlc_config_t& cnfg)
if (cnfg.rat == srslte_rat_t::lte) { if (cnfg.rat == srslte_rat_t::lte) {
switch (cnfg.rlc_mode) { switch (cnfg.rlc_mode) {
case rlc_mode_t::tm: case rlc_mode_t::tm:
rlc_entity = new rlc_tm(rlc_log, lcid, pdcp, rrc); rlc_entity = new rlc_tm(logger, lcid, pdcp, rrc);
break; break;
case rlc_mode_t::am: case rlc_mode_t::am:
rlc_entity = new rlc_am_lte(rlc_log, lcid, pdcp, rrc, timers); rlc_entity = new rlc_am_lte(logger, lcid, pdcp, rrc, timers);
break; break;
case rlc_mode_t::um: case rlc_mode_t::um:
rlc_entity = new rlc_um_lte(rlc_log, lcid, pdcp, rrc, timers); rlc_entity = new rlc_um_lte(logger, lcid, pdcp, rrc, timers);
break; break;
default: default:
rlc_log->error("Cannot add RLC entity - invalid mode\n"); logger.error("Cannot add RLC entity - invalid mode");
return; return;
} }
if (rlc_entity != nullptr) { if (rlc_entity != nullptr) {
@ -421,38 +421,38 @@ void rlc::add_bearer(uint32_t lcid, const rlc_config_t& cnfg)
} else if (cnfg.rat == srslte_rat_t::nr) { } else if (cnfg.rat == srslte_rat_t::nr) {
switch (cnfg.rlc_mode) { switch (cnfg.rlc_mode) {
case rlc_mode_t::tm: case rlc_mode_t::tm:
rlc_entity = new rlc_tm(rlc_log, lcid, pdcp, rrc); rlc_entity = new rlc_tm(logger, lcid, pdcp, rrc);
break; break;
case rlc_mode_t::um: case rlc_mode_t::um:
rlc_entity = new rlc_um_nr(rlc_log, lcid, pdcp, rrc, timers); rlc_entity = new rlc_um_nr(logger, lcid, pdcp, rrc, timers);
break; break;
default: default:
rlc_log->error("Cannot add RLC entity - invalid mode\n"); logger.error("Cannot add RLC entity - invalid mode");
return; return;
} }
#endif #endif
} else { } else {
rlc_log->error("RAT not supported\n"); logger.error("RAT not supported");
return; return;
} }
if (not rlc_array.insert(rlc_map_pair_t(lcid, rlc_entity)).second) { if (not rlc_array.insert(rlc_map_pair_t(lcid, rlc_entity)).second) {
rlc_log->error("Error inserting RLC entity in to array\n."); logger.error("Error inserting RLC entity in to array.");
goto delete_and_exit; goto delete_and_exit;
} }
rlc_log->info("Added radio bearer %s in %s\n", rrc->get_rb_name(lcid).c_str(), to_string(cnfg.rlc_mode).c_str()); logger.info("Added radio bearer %s in %s", rrc->get_rb_name(lcid).c_str(), to_string(cnfg.rlc_mode).c_str());
rlc_entity = NULL; rlc_entity = NULL;
} }
// configure and add to array // configure and add to array
if (cnfg.rlc_mode != rlc_mode_t::tm and rlc_array.find(lcid) != rlc_array.end()) { if (cnfg.rlc_mode != rlc_mode_t::tm and rlc_array.find(lcid) != rlc_array.end()) {
if (not rlc_array.at(lcid)->configure(cnfg)) { if (not rlc_array.at(lcid)->configure(cnfg)) {
rlc_log->error("Error configuring RLC entity\n."); logger.error("Error configuring RLC entity.");
goto delete_and_exit; goto delete_and_exit;
} }
} }
rlc_log->info("Configured radio bearer %s in %s\n", rrc->get_rb_name(lcid).c_str(), to_string(cnfg.rlc_mode).c_str()); logger.info("Configured radio bearer %s in %s", rrc->get_rb_name(lcid).c_str(), to_string(cnfg.rlc_mode).c_str());
delete_and_exit: delete_and_exit:
if (rlc_entity) { if (rlc_entity) {
@ -466,22 +466,22 @@ void rlc::add_bearer_mrb(uint32_t lcid)
rlc_common* rlc_entity = NULL; rlc_common* rlc_entity = NULL;
if (not valid_lcid_mrb(lcid)) { if (not valid_lcid_mrb(lcid)) {
rlc_entity = new rlc_um_lte(rlc_log, lcid, pdcp, rrc, timers); rlc_entity = new rlc_um_lte(logger, lcid, pdcp, rrc, timers);
// configure and add to array // configure and add to array
if (not rlc_entity->configure(rlc_config_t::mch_config())) { if (not rlc_entity->configure(rlc_config_t::mch_config())) {
rlc_log->error("Error configuring RLC entity\n."); logger.error("Error configuring RLC entity.");
goto delete_and_exit; goto delete_and_exit;
} }
if (rlc_array_mrb.count(lcid) == 0) { if (rlc_array_mrb.count(lcid) == 0) {
if (not rlc_array_mrb.insert(rlc_map_pair_t(lcid, rlc_entity)).second) { if (not rlc_array_mrb.insert(rlc_map_pair_t(lcid, rlc_entity)).second) {
rlc_log->error("Error inserting RLC entity in to array\n."); logger.error("Error inserting RLC entity in to array.");
goto delete_and_exit; goto delete_and_exit;
} }
} }
rlc_log->warning("Added bearer MRB%d with mode RLC_UM\n", lcid); logger.warning("Added bearer MRB%d with mode RLC_UM", lcid);
return; return;
} else { } else {
rlc_log->warning("Bearer MRB%d already created.\n", lcid); logger.warning("Bearer MRB%d already created.", lcid);
} }
delete_and_exit: delete_and_exit:
@ -499,9 +499,9 @@ void rlc::del_bearer(uint32_t lcid)
it->second->stop(); it->second->stop();
delete (it->second); delete (it->second);
rlc_array.erase(it); rlc_array.erase(it);
rlc_log->warning("Deleted RLC bearer %s\n", rrc->get_rb_name(lcid).c_str()); logger.warning("Deleted RLC bearer %s", rrc->get_rb_name(lcid).c_str());
} else { } else {
rlc_log->error("Can't delete bearer %s. Bearer doesn't exist.\n", rrc->get_rb_name(lcid).c_str()); logger.error("Can't delete bearer %s. Bearer doesn't exist.", rrc->get_rb_name(lcid).c_str());
} }
} }
@ -514,9 +514,9 @@ void rlc::del_bearer_mrb(uint32_t lcid)
it->second->stop(); it->second->stop();
delete (it->second); delete (it->second);
rlc_array_mrb.erase(it); rlc_array_mrb.erase(it);
rlc_log->warning("Deleted RLC MRB bearer %s\n", rrc->get_rb_name(lcid).c_str()); logger.warning("Deleted RLC MRB bearer %s", rrc->get_rb_name(lcid).c_str());
} else { } else {
rlc_log->error("Can't delete bearer %s. Bearer doesn't exist.\n", rrc->get_rb_name(lcid).c_str()); logger.error("Can't delete bearer %s. Bearer doesn't exist.", rrc->get_rb_name(lcid).c_str());
} }
} }
@ -530,19 +530,19 @@ void rlc::change_lcid(uint32_t old_lcid, uint32_t new_lcid)
rlc_map_t::iterator it = rlc_array.find(old_lcid); rlc_map_t::iterator it = rlc_array.find(old_lcid);
rlc_common* rlc_entity = it->second; rlc_common* rlc_entity = it->second;
if (not rlc_array.insert(rlc_map_pair_t(new_lcid, rlc_entity)).second) { if (not rlc_array.insert(rlc_map_pair_t(new_lcid, rlc_entity)).second) {
rlc_log->error("Error inserting RLC entity into array\n."); logger.error("Error inserting RLC entity into array.");
return; return;
} }
// erase from old position // erase from old position
rlc_array.erase(it); rlc_array.erase(it);
if (valid_lcid(new_lcid) && not valid_lcid(old_lcid)) { if (valid_lcid(new_lcid) && not valid_lcid(old_lcid)) {
rlc_log->info("Successfully changed LCID of RLC bearer from %d to %d\n", old_lcid, new_lcid); logger.info("Successfully changed LCID of RLC bearer from %d to %d", old_lcid, new_lcid);
} else { } else {
rlc_log->error("Error during LCID change of RLC bearer from %d to %d\n", old_lcid, new_lcid); logger.error("Error during LCID change of RLC bearer from %d to %d", old_lcid, new_lcid);
} }
} else { } else {
rlc_log->error("Can't change LCID of bearer %s from %d to %d. Bearer doesn't exist or new LCID already occupied.\n", logger.error("Can't change LCID of bearer %s from %d to %d. Bearer doesn't exist or new LCID already occupied.",
rrc->get_rb_name(old_lcid).c_str(), rrc->get_rb_name(old_lcid).c_str(),
old_lcid, old_lcid,
new_lcid); new_lcid);
@ -554,26 +554,26 @@ void rlc::suspend_bearer(uint32_t lcid)
{ {
if (valid_lcid(lcid)) { if (valid_lcid(lcid)) {
if (rlc_array.at(lcid)->suspend()) { if (rlc_array.at(lcid)->suspend()) {
rlc_log->info("Suspended radio bearer %s\n", rrc->get_rb_name(lcid).c_str()); logger.info("Suspended radio bearer %s", rrc->get_rb_name(lcid).c_str());
} else { } else {
rlc_log->error("Error suspending RLC entity: bearer already suspended\n."); logger.error("Error suspending RLC entity: bearer already suspended.");
} }
} else { } else {
rlc_log->error("Suspending bearer: bearer %s not configured.\n", rrc->get_rb_name(lcid).c_str()); logger.error("Suspending bearer: bearer %s not configured.", rrc->get_rb_name(lcid).c_str());
} }
} }
void rlc::resume_bearer(uint32_t lcid) void rlc::resume_bearer(uint32_t lcid)
{ {
rlc_log->info("Resuming radio bearer %s\n", rrc->get_rb_name(lcid).c_str()); logger.info("Resuming radio bearer %s", rrc->get_rb_name(lcid).c_str());
if (valid_lcid(lcid)) { if (valid_lcid(lcid)) {
if (rlc_array.at(lcid)->resume()) { if (rlc_array.at(lcid)->resume()) {
rlc_log->info("Resumed radio bearer %s\n", rrc->get_rb_name(lcid).c_str()); logger.info("Resumed radio bearer %s", rrc->get_rb_name(lcid).c_str());
} else { } else {
rlc_log->error("Error resuming RLC entity: bearer not suspended\n."); logger.error("Error resuming RLC entity: bearer not suspended.");
} }
} else { } else {
rlc_log->error("Resuming bearer: bearer %s not configured.\n", rrc->get_rb_name(lcid).c_str()); logger.error("Resuming bearer: bearer %s not configured.", rrc->get_rb_name(lcid).c_str());
} }
} }
@ -589,7 +589,7 @@ bool rlc::has_bearer(uint32_t lcid)
bool rlc::valid_lcid(uint32_t lcid) bool rlc::valid_lcid(uint32_t lcid)
{ {
if (lcid >= SRSLTE_N_RADIO_BEARERS) { if (lcid >= SRSLTE_N_RADIO_BEARERS) {
rlc_log->error("Radio bearer id must be in [0:%d] - %d\n", SRSLTE_N_RADIO_BEARERS, lcid); logger.error("Radio bearer id must be in [0:%d] - %d", SRSLTE_N_RADIO_BEARERS, lcid);
return false; return false;
} }
@ -603,7 +603,7 @@ bool rlc::valid_lcid(uint32_t lcid)
bool rlc::valid_lcid_mrb(uint32_t lcid) bool rlc::valid_lcid_mrb(uint32_t lcid)
{ {
if (lcid >= SRSLTE_N_MCH_LCIDS) { if (lcid >= SRSLTE_N_MCH_LCIDS) {
rlc_log->error("Radio bearer id must be in [0:%d] - %d\n", SRSLTE_N_RADIO_BEARERS, lcid); logger.error("Radio bearer id must be in [0:%d] - %d", SRSLTE_N_RADIO_BEARERS, lcid);
return false; return false;
} }

269
lib/src/upper/rlc_am_lte.cc
Unescape Escape View File

@ -23,12 +23,12 @@
namespace srslte { namespace srslte {
rlc_am_lte::rlc_am_lte(srslte::log_ref log_, rlc_am_lte::rlc_am_lte(srslog::basic_logger& logger,
uint32_t lcid_, uint32_t lcid_,
srsue::pdcp_interface_rlc* pdcp_, srsue::pdcp_interface_rlc* pdcp_,
srsue::rrc_interface_rlc* rrc_, srsue::rrc_interface_rlc* rrc_,
srslte::timer_handler* timers_) : srslte::timer_handler* timers_) :
log(log_), rrc(rrc_), pdcp(pdcp_), timers(timers_), lcid(lcid_), tx(this), rx(this) logger(logger), rrc(rrc_), pdcp(pdcp_), timers(timers_), lcid(lcid_), tx(this), rx(this)
{} {}
// Applies new configuration. Must be just reestablished or initiated // Applies new configuration. Must be just reestablished or initiated
@ -41,17 +41,17 @@ bool rlc_am_lte::configure(const rlc_config_t& cfg_)
cfg = cfg_; cfg = cfg_;
if (not rx.configure(cfg.am)) { if (not rx.configure(cfg.am)) {
log->error("Error configuring bearer (RX)\n"); logger.error("Error configuring bearer (RX)");
return false; return false;
} }
if (not tx.configure(cfg)) { if (not tx.configure(cfg)) {
log->error("Error configuring bearer (TX)\n"); logger.error("Error configuring bearer (TX)");
return false; return false;
} }
log->info("%s configured: t_poll_retx=%d, poll_pdu=%d, poll_byte=%d, max_retx_thresh=%d, " logger.info("%s configured: t_poll_retx=%d, poll_pdu=%d, poll_byte=%d, max_retx_thresh=%d, "
"t_reordering=%d, t_status_prohibit=%d\n", "t_reordering=%d, t_status_prohibit=%d",
rb_name.c_str(), rb_name.c_str(),
cfg.am.t_poll_retx, cfg.am.t_poll_retx,
cfg.am.poll_pdu, cfg.am.poll_pdu,
@ -75,14 +75,14 @@ void rlc_am_lte::empty_queue()
void rlc_am_lte::reestablish() void rlc_am_lte::reestablish()
{ {
log->debug("Reestablished bearer %s\n", rb_name.c_str()); logger.debug("Reestablished bearer %s", rb_name.c_str());
tx.reestablish(); // calls stop and enables tx again tx.reestablish(); // calls stop and enables tx again
rx.reestablish(); // calls only stop rx.reestablish(); // calls only stop
} }
void rlc_am_lte::stop() void rlc_am_lte::stop()
{ {
log->debug("Stopped bearer %s\n", rb_name.c_str()); logger.debug("Stopped bearer %s", rb_name.c_str());
tx.stop(); tx.stop();
rx.stop(); rx.stop();
} }
@ -167,7 +167,7 @@ void rlc_am_lte::write_pdu(uint8_t* payload, uint32_t nof_bytes)
rlc_am_lte::rlc_am_lte_tx::rlc_am_lte_tx(rlc_am_lte* parent_) : rlc_am_lte::rlc_am_lte_tx::rlc_am_lte_tx(rlc_am_lte* parent_) :
parent(parent_), parent(parent_),
log(parent_->log), logger(parent_->logger),
pool(byte_buffer_pool::get_instance()), pool(byte_buffer_pool::get_instance()),
poll_retx_timer(parent_->timers->get_unique_timer()), poll_retx_timer(parent_->timers->get_unique_timer()),
status_prohibit_timer(parent_->timers->get_unique_timer()) status_prohibit_timer(parent_->timers->get_unique_timer())
@ -192,7 +192,7 @@ bool rlc_am_lte::rlc_am_lte_tx::configure(const rlc_config_t& cfg_)
// check timers // check timers
if (not poll_retx_timer.is_valid() or not status_prohibit_timer.is_valid()) { if (not poll_retx_timer.is_valid() or not status_prohibit_timer.is_valid()) {
log->error("Configuring RLC AM TX: timers not configured\n"); logger.error("Configuring RLC AM TX: timers not configured");
return false; return false;
} }
@ -286,7 +286,7 @@ uint32_t rlc_am_lte::rlc_am_lte_tx::get_buffer_state()
uint32_t n_bytes = 0; uint32_t n_bytes = 0;
uint32_t n_sdus = 0; uint32_t n_sdus = 0;
log->debug("%s Buffer state - do_status=%s, status_prohibit_running=%s (%d/%d)\n", logger.debug("%s Buffer state - do_status=%s, status_prohibit_running=%s (%d/%d)",
RB_NAME, RB_NAME,
do_status() ? "yes" : "no", do_status() ? "yes" : "no",
status_prohibit_timer.is_running() ? "yes" : "no", status_prohibit_timer.is_running() ? "yes" : "no",
@ -296,13 +296,13 @@ uint32_t rlc_am_lte::rlc_am_lte_tx::get_buffer_state()
// Bytes needed for status report // Bytes needed for status report
if (do_status() && not status_prohibit_timer.is_running()) { if (do_status() && not status_prohibit_timer.is_running()) {
n_bytes += parent->rx.get_status_pdu_length(); n_bytes += parent->rx.get_status_pdu_length();
log->debug("%s Buffer state - total status report: %d bytes\n", RB_NAME, n_bytes); logger.debug("%s Buffer state - total status report: %d bytes", RB_NAME, n_bytes);
} }
// Bytes needed for retx // 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();
log->debug("%s Buffer state - retx - SN=%d, Segment: %s, %d:%d\n", logger.debug("%s Buffer state - retx - SN=%d, Segment: %s, %d:%d",
RB_NAME, RB_NAME,
retx.sn, retx.sn,
retx.is_segment ? "true" : "false", retx.is_segment ? "true" : "false",
@ -311,11 +311,11 @@ uint32_t rlc_am_lte::rlc_am_lte_tx::get_buffer_state()
if (tx_window.end() != tx_window.find(retx.sn)) { if (tx_window.end() != tx_window.find(retx.sn)) {
int req_bytes = required_buffer_size(retx); int req_bytes = required_buffer_size(retx);
if (req_bytes < 0) { if (req_bytes < 0) {
log->error("In get_buffer_state(): Removing retx.sn=%d from queue\n", retx.sn); logger.error("In get_buffer_state(): Removing retx.sn=%d from queue", retx.sn);
retx_queue.pop_front(); retx_queue.pop_front();
} else { } else {
n_bytes += req_bytes; n_bytes += req_bytes;
log->debug("Buffer state - retx: %d bytes\n", n_bytes); logger.debug("Buffer state - retx: %d bytes", n_bytes);
} }
} }
} }
@ -338,7 +338,7 @@ uint32_t rlc_am_lte::rlc_am_lte_tx::get_buffer_state()
// Room needed for fixed header of data PDUs // Room needed for fixed header of data PDUs
if (n_bytes > 0 && n_sdus > 0) { if (n_bytes > 0 && n_sdus > 0) {
n_bytes += 2; // Two bytes for fixed header with SN length = 10 n_bytes += 2; // Two bytes for fixed header with SN length = 10
log->debug("%s Total buffer state - %d SDUs (%d B)\n", RB_NAME, n_sdus, n_bytes); logger.debug("%s Total buffer state - %d SDUs (%d B)", RB_NAME, n_sdus, n_bytes);
} }
pthread_mutex_unlock(&mutex); pthread_mutex_unlock(&mutex);
@ -355,7 +355,7 @@ int rlc_am_lte::rlc_am_lte_tx::write_sdu(unique_byte_buffer_t sdu)
} }
if (sdu.get() == nullptr) { if (sdu.get() == nullptr) {
log->warning("NULL SDU pointer in write_sdu()\n"); logger.warning("NULL SDU pointer in write_sdu()");
pthread_mutex_unlock(&mutex); pthread_mutex_unlock(&mutex);
return SRSLTE_ERROR; return SRSLTE_ERROR;
} }
@ -369,13 +369,12 @@ int rlc_am_lte::rlc_am_lte_tx::write_sdu(unique_byte_buffer_t sdu)
uint32_t nof_bytes = sdu->N_bytes; uint32_t nof_bytes = sdu->N_bytes;
srslte::error_type<unique_byte_buffer_t> ret = tx_sdu_queue.try_write(std::move(sdu)); srslte::error_type<unique_byte_buffer_t> ret = tx_sdu_queue.try_write(std::move(sdu));
if (ret) { if (ret) {
log->info_hex( logger.info(msg_ptr, nof_bytes, "%s Tx SDU (%d B, tx_sdu_queue_len=%d)", RB_NAME, nof_bytes, tx_sdu_queue.size());
msg_ptr, nof_bytes, "%s Tx SDU (%d B, tx_sdu_queue_len=%d)\n", RB_NAME, nof_bytes, tx_sdu_queue.size());
} else { } else {
// in case of fail, the try_write returns back the sdu // in case of fail, the try_write returns back the sdu
log->warning_hex(ret.error()->msg, logger.warning(ret.error()->msg,
ret.error()->N_bytes, ret.error()->N_bytes,
"[Dropped SDU] %s Tx SDU (%d B, tx_sdu_queue_len=%d)\n", "[Dropped SDU] %s Tx SDU (%d B, tx_sdu_queue_len=%d)",
RB_NAME, RB_NAME,
ret.error()->N_bytes, ret.error()->N_bytes,
tx_sdu_queue.size()); tx_sdu_queue.size());
@ -386,17 +385,17 @@ int rlc_am_lte::rlc_am_lte_tx::write_sdu(unique_byte_buffer_t sdu)
// Store SDU info // Store SDU info
uint32_t info_count = undelivered_sdu_info_queue.count(info.sn); uint32_t info_count = undelivered_sdu_info_queue.count(info.sn);
if (info_count != 0) { if (info_count != 0) {
log->error("PDCP SDU info already exists. SN=%d\n", info.sn); logger.error("PDCP SDU info already exists. SN=%d", info.sn);
pthread_mutex_unlock(&mutex); pthread_mutex_unlock(&mutex);
return SRSLTE_ERROR; return SRSLTE_ERROR;
} }
if (undelivered_sdu_info_queue.size() >= pdcp_info_queue_capacity) { if (undelivered_sdu_info_queue.size() >= pdcp_info_queue_capacity) {
log->warning("Undelivered PDCP SDU info queue is growing large. Queue size: %ld\n", logger.warning("Undelivered PDCP SDU info queue is growing large. Queue size: %ld",
undelivered_sdu_info_queue.size()); undelivered_sdu_info_queue.size());
} }
log->debug("Adding SDU info for PDCP_SN=%d", info.sn); logger.debug("Adding SDU info for PDCP_SN=%d", info.sn);
undelivered_sdu_info_queue[info.sn] = info; undelivered_sdu_info_queue[info.sn] = info;
pthread_mutex_unlock(&mutex); pthread_mutex_unlock(&mutex);
return SRSLTE_SUCCESS; return SRSLTE_SUCCESS;
@ -407,7 +406,7 @@ void rlc_am_lte::rlc_am_lte_tx::discard_sdu(uint32_t discard_sn)
if (!tx_enabled) { if (!tx_enabled) {
return; return;
} }
log->warning("Discard SDU not implemented yet\n"); logger.warning("Discard SDU not implemented yet");
} }
bool rlc_am_lte::rlc_am_lte_tx::sdu_queue_is_full() bool rlc_am_lte::rlc_am_lte_tx::sdu_queue_is_full()
@ -425,11 +424,11 @@ int rlc_am_lte::rlc_am_lte_tx::read_pdu(uint8_t* payload, uint32_t nof_bytes)
goto unlock_and_exit; goto unlock_and_exit;
} }
log->debug("MAC opportunity - %d bytes\n", nof_bytes); logger.debug("MAC opportunity - %d bytes", nof_bytes);
log->debug("tx_window size - %zu PDUs\n", tx_window.size()); logger.debug("tx_window size - %zu PDUs", tx_window.size());
if (not tx_enabled) { if (not tx_enabled) {
log->debug("RLC entity not active. Not generating PDU.\n"); logger.debug("RLC entity not active. Not generating PDU.");
goto unlock_and_exit; goto unlock_and_exit;
} }
@ -464,7 +463,7 @@ void rlc_am_lte::rlc_am_lte_tx::timer_expired(uint32_t timeout_id)
{ {
pthread_mutex_lock(&mutex); pthread_mutex_lock(&mutex);
if (poll_retx_timer.is_valid() && poll_retx_timer.id() == timeout_id) { if (poll_retx_timer.is_valid() && poll_retx_timer.id() == timeout_id) {
log->debug("%s Poll reTx timer expired after %dms\n", RB_NAME, poll_retx_timer.duration()); logger.debug("%s Poll reTx timer expired after %dms", RB_NAME, poll_retx_timer.duration());
// Section 5.2.2.3 in TS 36.311, schedule PDU for retransmission if // Section 5.2.2.3 in TS 36.311, schedule PDU for retransmission if
// (a) both tx and retx buffer are empty, or // (a) both tx and retx buffer are empty, or
// (b) no new data PDU can be transmitted (tx window is full) // (b) no new data PDU can be transmitted (tx window is full)
@ -484,7 +483,7 @@ void rlc_am_lte::rlc_am_lte_tx::retransmit_pdu()
if (not tx_window.empty()) { if (not tx_window.empty()) {
// select PDU in tx window for retransmission // select PDU in tx window for retransmission
std::map<uint32_t, rlc_amd_tx_pdu_t>::iterator it = tx_window.begin(); std::map<uint32_t, rlc_amd_tx_pdu_t>::iterator it = tx_window.begin();
log->info("%s Schedule SN=%d for reTx.\n", RB_NAME, it->first); logger.info("%s Schedule SN=%d for reTx.", RB_NAME, it->first);
rlc_amd_retx_t retx = {}; rlc_amd_retx_t retx = {};
retx.is_segment = false; retx.is_segment = false;
retx.so_start = 0; retx.so_start = 0;
@ -544,9 +543,9 @@ bool rlc_am_lte::rlc_am_lte_tx::poll_required()
int rlc_am_lte::rlc_am_lte_tx::build_status_pdu(uint8_t* payload, uint32_t nof_bytes) int rlc_am_lte::rlc_am_lte_tx::build_status_pdu(uint8_t* payload, uint32_t nof_bytes)
{ {
int pdu_len = parent->rx.get_status_pdu(&tx_status, nof_bytes); int pdu_len = parent->rx.get_status_pdu(&tx_status, nof_bytes);
log->debug("%s\n", rlc_am_status_pdu_to_string(&tx_status).c_str()); logger.debug("%s", rlc_am_status_pdu_to_string(&tx_status).c_str());
if (pdu_len > 0 && nof_bytes >= static_cast<uint32_t>(pdu_len)) { if (pdu_len > 0 && nof_bytes >= static_cast<uint32_t>(pdu_len)) {
log->info("%s Tx status PDU - %s\n", RB_NAME, rlc_am_status_pdu_to_string(&tx_status).c_str()); logger.info("%s Tx status PDU - %s", RB_NAME, rlc_am_status_pdu_to_string(&tx_status).c_str());
parent->rx.reset_status(); parent->rx.reset_status();
@ -557,7 +556,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_status_pdu(uint8_t* payload, uint32_t nof_b
debug_state(); debug_state();
pdu_len = rlc_am_write_status_pdu(&tx_status, payload); pdu_len = rlc_am_write_status_pdu(&tx_status, payload);
} else { } else {
log->info("%s Cannot tx status PDU - %d bytes available, %d bytes required\n", RB_NAME, nof_bytes, pdu_len); logger.info("%s Cannot tx status PDU - %d bytes available, %d bytes required", RB_NAME, nof_bytes, pdu_len);
pdu_len = 0; pdu_len = 0;
} }
@ -568,7 +567,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt
{ {
// Check there is at least 1 element before calling front() // Check there is at least 1 element before calling front()
if (retx_queue.empty()) { if (retx_queue.empty()) {
log->error("In build_retx_pdu(): retx_queue is empty\n"); logger.error("In build_retx_pdu(): retx_queue is empty");
return -1; return -1;
} }
@ -580,7 +579,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt
if (!retx_queue.empty()) { if (!retx_queue.empty()) {
retx = retx_queue.front(); retx = retx_queue.front();
} else { } else {
log->info("In build_retx_pdu(): retx_queue is empty during sanity check, sn=%d\n", retx.sn); logger.info("In build_retx_pdu(): retx_queue is empty during sanity check, sn=%d", retx.sn);
return 0; return 0;
} }
} }
@ -588,13 +587,13 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt
// Is resegmentation needed? // Is resegmentation needed?
int req_size = required_buffer_size(retx); int req_size = required_buffer_size(retx);
if (req_size < 0) { if (req_size < 0) {
log->error("In build_retx_pdu(): Removing retx.sn=%d from queue\n", retx.sn); logger.error("In build_retx_pdu(): Removing retx.sn=%d from queue", retx.sn);
retx_queue.pop_front(); retx_queue.pop_front();
return -1; return -1;
} }
if (retx.is_segment || req_size > static_cast<int>(nof_bytes)) { if (retx.is_segment || req_size > static_cast<int>(nof_bytes)) {
log->debug("%s build_retx_pdu - resegmentation required\n", RB_NAME); logger.debug("%s build_retx_pdu - resegmentation required", RB_NAME);
return build_segment(payload, nof_bytes, retx); return build_segment(payload, nof_bytes, retx);
} }
@ -605,8 +604,8 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt
// Set poll bit // Set poll bit
pdu_without_poll++; pdu_without_poll++;
byte_without_poll += (tx_window[retx.sn].buf->N_bytes + rlc_am_packed_length(&new_header)); byte_without_poll += (tx_window[retx.sn].buf->N_bytes + rlc_am_packed_length(&new_header));
log->info("%s pdu_without_poll: %d\n", RB_NAME, pdu_without_poll); logger.info("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll);
log->info("%s byte_without_poll: %d\n", RB_NAME, byte_without_poll); logger.info("%s byte_without_poll: %d", RB_NAME, byte_without_poll);
if (poll_required()) { if (poll_required()) {
new_header.p = 1; new_header.p = 1;
// vt_s won't change for reTx, so don't update poll_sn // vt_s won't change for reTx, so don't update poll_sn
@ -625,19 +624,19 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt
retx_queue.pop_front(); retx_queue.pop_front();
tx_window[retx.sn].retx_count++; tx_window[retx.sn].retx_count++;
if (tx_window[retx.sn].retx_count >= cfg.max_retx_thresh) { if (tx_window[retx.sn].retx_count >= cfg.max_retx_thresh) {
log->warning("%s Signaling max number of reTx=%d for for SN=%d\n", RB_NAME, tx_window[retx.sn].retx_count, retx.sn); logger.warning("%s Signaling max number of reTx=%d for for SN=%d", RB_NAME, tx_window[retx.sn].retx_count, retx.sn);
parent->rrc->max_retx_attempted(); parent->rrc->max_retx_attempted();
} }
log->info_hex(payload, logger.info(payload,
tx_window[retx.sn].buf->N_bytes, tx_window[retx.sn].buf->N_bytes,
"%s Tx PDU SN=%d (%d B) (attempt %d/%d)\n", "%s Tx PDU SN=%d (%d B) (attempt %d/%d)",
RB_NAME, RB_NAME,
retx.sn, retx.sn,
tx_window[retx.sn].buf->N_bytes, tx_window[retx.sn].buf->N_bytes,
tx_window[retx.sn].retx_count + 1, tx_window[retx.sn].retx_count + 1,
cfg.max_retx_thresh); cfg.max_retx_thresh);
log->debug("%s\n", rlc_amd_pdu_header_to_string(new_header).c_str()); logger.debug("%s", rlc_amd_pdu_header_to_string(new_header).c_str());
debug_state(); debug_state();
return (ptr - payload) + tx_window[retx.sn].buf->N_bytes; return (ptr - payload) + tx_window[retx.sn].buf->N_bytes;
@ -646,7 +645,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_retx_pdu(uint8_t* payload, uint32_t nof_byt
int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_bytes, rlc_amd_retx_t retx) int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_bytes, rlc_amd_retx_t retx)
{ {
if (tx_window[retx.sn].buf == NULL) { if (tx_window[retx.sn].buf == NULL) {
log->error("In build_segment: retx.sn=%d has null buffer\n", retx.sn); logger.error("In build_segment: retx.sn=%d has null buffer", retx.sn);
return 0; return 0;
} }
if (!retx.is_segment) { if (!retx.is_segment) {
@ -660,8 +659,8 @@ int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_byte
pdu_without_poll++; pdu_without_poll++;
byte_without_poll += (tx_window[retx.sn].buf->N_bytes + rlc_am_packed_length(&new_header)); byte_without_poll += (tx_window[retx.sn].buf->N_bytes + rlc_am_packed_length(&new_header));
log->info("%s pdu_without_poll: %d\n", RB_NAME, pdu_without_poll); logger.info("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll);
log->info("%s byte_without_poll: %d\n", RB_NAME, byte_without_poll); logger.info("%s byte_without_poll: %d", RB_NAME, byte_without_poll);
new_header.dc = RLC_DC_FIELD_DATA_PDU; new_header.dc = RLC_DC_FIELD_DATA_PDU;
new_header.rf = 1; new_header.rf = 1;
@ -672,7 +671,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_byte
new_header.N_li = 0; new_header.N_li = 0;
new_header.p = 0; new_header.p = 0;
if (poll_required()) { if (poll_required()) {
log->debug("%s setting poll bit to request status\n", RB_NAME); logger.debug("%s setting poll bit to request status", RB_NAME);
new_header.p = 1; new_header.p = 1;
// vt_s won't change for reTx, so don't update poll_sn // vt_s won't change for reTx, so don't update poll_sn
pdu_without_poll = 0; pdu_without_poll = 0;
@ -692,7 +691,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_byte
} }
if (nof_bytes <= head_len) { if (nof_bytes <= head_len) {
log->info("%s Cannot build a PDU segment - %d bytes available, %d bytes required for header\n", logger.info("%s Cannot build a PDU segment - %d bytes available, %d bytes required for header",
RB_NAME, RB_NAME,
nof_bytes, nof_bytes,
head_len); head_len);
@ -788,18 +787,18 @@ int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_byte
debug_state(); debug_state();
int pdu_len = (ptr - payload) + len; int pdu_len = (ptr - payload) + len;
if (pdu_len > static_cast<int>(nof_bytes)) { if (pdu_len > static_cast<int>(nof_bytes)) {
log->error("%s Retx PDU segment length error. Available: %d, Used: %d\n", RB_NAME, nof_bytes, pdu_len); logger.error("%s Retx PDU segment length error. Available: %d, Used: %d", RB_NAME, nof_bytes, pdu_len);
int header_len = (ptr - payload); int header_len = (ptr - payload);
log->debug("%s Retx PDU segment length error. Header len: %d, Payload len: %d, N_li: %d\n", logger.debug("%s Retx PDU segment length error. Header len: %d, Payload len: %d, N_li: %d",
RB_NAME, RB_NAME,
header_len, header_len,
len, len,
new_header.N_li); new_header.N_li);
} }
log->info_hex(payload, logger.info(payload,
pdu_len, pdu_len,
"%s Retx PDU segment SN=%d [so=%d] (%d B) (attempt %d/%d)\n", "%s Retx PDU segment SN=%d [so=%d] (%d B) (attempt %d/%d)",
RB_NAME, RB_NAME,
retx.sn, retx.sn,
retx.so_start, retx.so_start,
@ -813,13 +812,13 @@ int rlc_am_lte::rlc_am_lte_tx::build_segment(uint8_t* payload, uint32_t nof_byte
int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes) int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_bytes)
{ {
if (tx_sdu == NULL && tx_sdu_queue.is_empty()) { if (tx_sdu == NULL && tx_sdu_queue.is_empty()) {
log->info("No data available to be sent\n"); logger.info("No data available to be sent");
return 0; return 0;
} }
// do not build any more PDU if window is already full // do not build any more PDU if window is already full
if (tx_sdu == NULL && tx_window.size() >= RLC_AM_WINDOW_SIZE) { if (tx_sdu == NULL && tx_window.size() >= RLC_AM_WINDOW_SIZE) {
log->info("Tx window full.\n"); logger.info("Tx window full.");
return 0; return 0;
} }
@ -836,7 +835,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
} }
exit(-1); exit(-1);
#else #else
log->error("Fatal Error: Couldn't allocate PDU in build_data_pdu().\n"); logger.error("Fatal Error: Couldn't allocate PDU in build_data_pdu().");
return 0; return 0;
#endif #endif
} }
@ -852,12 +851,12 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
uint8_t* pdu_ptr = pdu->msg; uint8_t* pdu_ptr = pdu->msg;
if (pdu_space <= head_len) { if (pdu_space <= head_len) {
log->info( logger.info(
"%s Cannot build a PDU - %d bytes available, %d bytes required for header\n", RB_NAME, nof_bytes, head_len); "%s Cannot build a PDU - %d bytes available, %d bytes required for header", RB_NAME, nof_bytes, head_len);
return 0; return 0;
} }
log->debug("%s Building PDU - pdu_space: %d, head_len: %d \n", RB_NAME, pdu_space, head_len); logger.debug("%s Building PDU - pdu_space: %d, head_len: %d ", RB_NAME, pdu_space, head_len);
// Check for SDU segment // Check for SDU segment
if (tx_sdu != NULL) { if (tx_sdu != NULL) {
@ -870,12 +869,12 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
tx_sdu->msg += to_move; tx_sdu->msg += to_move;
auto info_it = undelivered_sdu_info_queue.find(tx_sdu->md.pdcp_sn); auto info_it = undelivered_sdu_info_queue.find(tx_sdu->md.pdcp_sn);
if (info_it == undelivered_sdu_info_queue.end()) { if (info_it == undelivered_sdu_info_queue.end()) {
log->error("Could not find PDCP SN in SDU info queue (segment). PDCP_SN=%d\n", tx_sdu->md.pdcp_sn); logger.error("Could not find PDCP SN in SDU info queue (segment). PDCP_SN=%d", tx_sdu->md.pdcp_sn);
return 0; return 0;
} }
undelivered_sdu_info_queue.at(tx_sdu->md.pdcp_sn).rlc_sn_info_list.push_back({header.sn, false}); undelivered_sdu_info_queue.at(tx_sdu->md.pdcp_sn).rlc_sn_info_list.push_back({header.sn, false});
if (tx_sdu->N_bytes == 0) { if (tx_sdu->N_bytes == 0) {
log->debug("%s Complete SDU scheduled for tx.\n", RB_NAME); logger.debug("%s Complete SDU scheduled for tx.", RB_NAME);
undelivered_sdu_info_queue[tx_sdu->md.pdcp_sn].fully_txed = true; undelivered_sdu_info_queue[tx_sdu->md.pdcp_sn].fully_txed = true;
tx_sdu.reset(); tx_sdu.reset();
} }
@ -886,7 +885,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
} }
header.fi |= RLC_FI_FIELD_NOT_START_ALIGNED; // First byte does not correspond to first byte of SDU header.fi |= RLC_FI_FIELD_NOT_START_ALIGNED; // First byte does not correspond to first byte of SDU
log->debug("%s Building PDU - added SDU segment (len:%d) - pdu_space: %d, head_len: %d \n", logger.debug("%s Building PDU - added SDU segment (len:%d) - pdu_space: %d, head_len: %d ",
RB_NAME, RB_NAME,
to_move, to_move,
pdu_space, pdu_space,
@ -916,12 +915,12 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
tx_sdu->msg += to_move; tx_sdu->msg += to_move;
auto info_it = undelivered_sdu_info_queue.find(tx_sdu->md.pdcp_sn); auto info_it = undelivered_sdu_info_queue.find(tx_sdu->md.pdcp_sn);
if (info_it == undelivered_sdu_info_queue.end()) { if (info_it == undelivered_sdu_info_queue.end()) {
log->error("Could not find PDCP SN in SDU info queue. PDCP_SN=%d\n", tx_sdu->md.pdcp_sn); logger.error("Could not find PDCP SN in SDU info queue. PDCP_SN=%d", tx_sdu->md.pdcp_sn);
return 0; return 0;
} }
info_it->second.rlc_sn_info_list.push_back({header.sn, false}); info_it->second.rlc_sn_info_list.push_back({header.sn, false});
if (tx_sdu->N_bytes == 0) { if (tx_sdu->N_bytes == 0) {
log->debug("%s Complete SDU scheduled for tx. PDCP SN=%d\n", RB_NAME, tx_sdu->md.pdcp_sn); logger.debug("%s Complete SDU scheduled for tx. PDCP SN=%d", RB_NAME, tx_sdu->md.pdcp_sn);
undelivered_sdu_info_queue[tx_sdu->md.pdcp_sn].fully_txed = true; undelivered_sdu_info_queue[tx_sdu->md.pdcp_sn].fully_txed = true;
tx_sdu.reset(); tx_sdu.reset();
} }
@ -931,7 +930,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
pdu_space = 0; pdu_space = 0;
} }
log->debug("%s Building PDU - added SDU segment (len:%d) - pdu_space: %d, head_len: %d \n", logger.debug("%s Building PDU - added SDU segment (len:%d) - pdu_space: %d, head_len: %d ",
RB_NAME, RB_NAME,
to_move, to_move,
pdu_space, pdu_space,
@ -940,7 +939,7 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
// Make sure, at least one SDU (segment) has been added until this point // Make sure, at least one SDU (segment) has been added until this point
if (pdu->N_bytes == 0) { if (pdu->N_bytes == 0) {
log->error("Generated empty RLC PDU.\n"); logger.error("Generated empty RLC PDU.");
return 0; return 0;
} }
@ -951,10 +950,10 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
// Set Poll bit // Set Poll bit
pdu_without_poll++; pdu_without_poll++;
byte_without_poll += (pdu->N_bytes + head_len); byte_without_poll += (pdu->N_bytes + head_len);
log->debug("%s pdu_without_poll: %d\n", RB_NAME, pdu_without_poll); logger.debug("%s pdu_without_poll: %d", RB_NAME, pdu_without_poll);
log->debug("%s byte_without_poll: %d\n", RB_NAME, byte_without_poll); logger.debug("%s byte_without_poll: %d", RB_NAME, byte_without_poll);
if (poll_required()) { if (poll_required()) {
log->debug("%s setting poll bit to request status\n", RB_NAME); logger.debug("%s setting poll bit to request status", RB_NAME);
header.p = 1; header.p = 1;
poll_sn = vt_s; poll_sn = vt_s;
pdu_without_poll = 0; pdu_without_poll = 0;
@ -979,8 +978,8 @@ int rlc_am_lte::rlc_am_lte_tx::build_data_pdu(uint8_t* payload, uint32_t nof_byt
rlc_am_write_data_pdu_header(&header, &ptr); rlc_am_write_data_pdu_header(&header, &ptr);
memcpy(ptr, buffer_ptr->msg, buffer_ptr->N_bytes); memcpy(ptr, buffer_ptr->msg, buffer_ptr->N_bytes);
int total_len = (ptr - payload) + buffer_ptr->N_bytes; int total_len = (ptr - payload) + buffer_ptr->N_bytes;
log->info_hex(payload, total_len, "%s Tx PDU SN=%d (%d B)\n", RB_NAME, header.sn, total_len); logger.info(payload, total_len, "%s Tx PDU SN=%d (%d B)", RB_NAME, header.sn, total_len);
log->debug("%s\n", rlc_amd_pdu_header_to_string(header).c_str()); logger.debug("%s", rlc_amd_pdu_header_to_string(header).c_str());
debug_state(); debug_state();
return total_len; return total_len;
@ -994,17 +993,17 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no
pthread_mutex_lock(&mutex); pthread_mutex_lock(&mutex);
log->info_hex(payload, nof_bytes, "%s Rx control PDU", RB_NAME); logger.info(payload, nof_bytes, "%s Rx control PDU", RB_NAME);
rlc_status_pdu_t status; rlc_status_pdu_t status;
rlc_am_read_status_pdu(payload, nof_bytes, &status); rlc_am_read_status_pdu(payload, nof_bytes, &status);
log->info("%s Rx Status PDU: %s\n", RB_NAME, rlc_am_status_pdu_to_string(&status).c_str()); logger.info("%s Rx Status PDU: %s", RB_NAME, rlc_am_status_pdu_to_string(&status).c_str());
// Sec 5.2.2.2, stop poll reTx timer if status PDU comprises a positive _or_ negative acknowledgement // 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 // 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))) { if (poll_retx_timer.is_valid() && (TX_MOD_BASE(poll_sn) < TX_MOD_BASE(status.ack_sn))) {
log->debug("%s Stopping pollRetx timer\n", RB_NAME); logger.debug("%s Stopping pollRetx timer", RB_NAME);
poll_retx_timer.stop(); poll_retx_timer.stop();
} }
@ -1038,7 +1037,7 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no
// sanity check // sanity check
if (status.nacks[j].so_start >= it->second.buf->N_bytes) { if (status.nacks[j].so_start >= it->second.buf->N_bytes) {
// print error but try to send original PDU again // print error but try to send original PDU again
log->info("SO_start is larger than original PDU (%d >= %d)\n", logger.info("SO_start is larger than original PDU (%d >= %d)",
status.nacks[j].so_start, status.nacks[j].so_start,
it->second.buf->N_bytes); it->second.buf->N_bytes);
status.nacks[j].so_start = 0; status.nacks[j].so_start = 0;
@ -1056,7 +1055,7 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no
retx.is_segment = true; retx.is_segment = true;
retx.so_start = status.nacks[j].so_start; retx.so_start = status.nacks[j].so_start;
} else { } else {
log->warning("%s invalid segment NACK received for SN %d. so_start: %d, so_end: %d, N_bytes: %d\n", logger.warning("%s invalid segment NACK received for SN %d. so_start: %d, so_end: %d, N_bytes: %d",
RB_NAME, RB_NAME,
i, i,
status.nacks[j].so_start, status.nacks[j].so_start,
@ -1092,10 +1091,10 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no
// Remove all SDUs that were fully acked // Remove all SDUs that were fully acked
for (uint32_t acked_pdcp_sn : notify_info_vec) { for (uint32_t acked_pdcp_sn : notify_info_vec) {
log->debug("Erasing SDU info: PDCP_SN=%d\n", acked_pdcp_sn); logger.debug("Erasing SDU info: PDCP_SN=%d", acked_pdcp_sn);
size_t erased = undelivered_sdu_info_queue.erase(acked_pdcp_sn); size_t erased = undelivered_sdu_info_queue.erase(acked_pdcp_sn);
if (erased == 0) { if (erased == 0) {
log->error("Could not find info to erase: SN=%d\n", acked_pdcp_sn); logger.error("Could not find info to erase: SN=%d", acked_pdcp_sn);
} }
} }
} }
@ -1113,7 +1112,7 @@ void rlc_am_lte::rlc_am_lte_tx::handle_control_pdu(uint8_t* payload, uint32_t no
void rlc_am_lte::rlc_am_lte_tx::update_notification_ack_info(const rlc_amd_tx_pdu_t& tx_pdu, void rlc_am_lte::rlc_am_lte_tx::update_notification_ack_info(const rlc_amd_tx_pdu_t& tx_pdu,
std::vector<uint32_t>& notify_info_vec) std::vector<uint32_t>& notify_info_vec)
{ {
log->debug("Updating ACK info: RLC SN=%d, number of notified SDU=%ld, number of undelivered SDUs=%ld", logger.debug("Updating ACK info: RLC SN=%d, number of notified SDU=%ld, number of undelivered SDUs=%ld",
tx_pdu.header.sn, tx_pdu.header.sn,
notify_info_vec.size(), notify_info_vec.size(),
undelivered_sdu_info_queue.size()); undelivered_sdu_info_queue.size());
@ -1143,7 +1142,7 @@ void rlc_am_lte::rlc_am_lte_tx::update_notification_ack_info(const rlc_amd_tx_pd
void rlc_am_lte::rlc_am_lte_tx::debug_state() void rlc_am_lte::rlc_am_lte_tx::debug_state()
{ {
log->debug("%s vt_a = %d, vt_ms = %d, vt_s = %d, poll_sn = %d\n", RB_NAME, vt_a, vt_ms, vt_s, poll_sn); logger.debug("%s vt_a = %d, vt_ms = %d, vt_s = %d, poll_sn = %d", RB_NAME, vt_a, vt_ms, vt_s, poll_sn);
} }
int rlc_am_lte::rlc_am_lte_tx::required_buffer_size(rlc_amd_retx_t retx) int rlc_am_lte::rlc_am_lte_tx::required_buffer_size(rlc_amd_retx_t retx)
@ -1153,11 +1152,11 @@ int rlc_am_lte::rlc_am_lte_tx::required_buffer_size(rlc_amd_retx_t retx)
if (tx_window[retx.sn].buf) { if (tx_window[retx.sn].buf) {
return rlc_am_packed_length(&tx_window[retx.sn].header) + tx_window[retx.sn].buf->N_bytes; return rlc_am_packed_length(&tx_window[retx.sn].header) + tx_window[retx.sn].buf->N_bytes;
} else { } else {
log->warning("retx.sn=%d has null ptr in required_buffer_size()\n", retx.sn); logger.warning("retx.sn=%d has null ptr in required_buffer_size()", retx.sn);
return -1; return -1;
} }
} else { } else {
log->warning("retx.sn=%d does not exist in required_buffer_size()\n", retx.sn); logger.warning("retx.sn=%d does not exist in required_buffer_size()", retx.sn);
return -1; return -1;
} }
} }
@ -1237,7 +1236,7 @@ bool rlc_am_lte::rlc_am_lte_tx::retx_queue_has_sn(uint32_t sn)
rlc_am_lte::rlc_am_lte_rx::rlc_am_lte_rx(rlc_am_lte* parent_) : rlc_am_lte::rlc_am_lte_rx::rlc_am_lte_rx(rlc_am_lte* parent_) :
parent(parent_), parent(parent_),
pool(byte_buffer_pool::get_instance()), pool(byte_buffer_pool::get_instance()),
log(parent_->log), logger(parent_->logger),
reordering_timer(parent_->timers->get_unique_timer()) reordering_timer(parent_->timers->get_unique_timer())
{ {
pthread_mutex_init(&mutex, NULL); pthread_mutex_init(&mutex, NULL);
@ -1255,7 +1254,7 @@ bool rlc_am_lte::rlc_am_lte_rx::configure(rlc_am_config_t cfg_)
// check timers // check timers
if (not reordering_timer.is_valid()) { if (not reordering_timer.is_valid()) {
log->error("Configuring RLC AM TX: timers not configured\n"); logger.error("Configuring RLC AM TX: timers not configured");
return false; return false;
} }
@ -1310,8 +1309,8 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
{ {
std::map<uint32_t, rlc_amd_rx_pdu_t>::iterator it; std::map<uint32_t, rlc_amd_rx_pdu_t>::iterator it;
log->info_hex(payload, nof_bytes, "%s Rx data PDU SN=%d (%d B)", RB_NAME, header.sn, nof_bytes); logger.info(payload, nof_bytes, "%s Rx data PDU SN=%d (%d B)", RB_NAME, header.sn, nof_bytes);
log->debug("%s\n", rlc_amd_pdu_header_to_string(header).c_str()); logger.debug("%s", rlc_amd_pdu_header_to_string(header).c_str());
// sanity check for segments not exceeding PDU length // sanity check for segments not exceeding PDU length
if (header.N_li > 0) { if (header.N_li > 0) {
@ -1319,7 +1318,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
for (uint32_t i = 0; i < header.N_li; i++) { for (uint32_t i = 0; i < header.N_li; i++) {
segments_len += header.li[i]; segments_len += header.li[i];
if (segments_len > nof_bytes) { if (segments_len > nof_bytes) {
log->info("Dropping corrupted PDU (segments_len=%d > pdu_len=%d)\n", segments_len, nof_bytes); logger.info("Dropping corrupted PDU (segments_len=%d > pdu_len=%d)", segments_len, nof_bytes);
return; return;
} }
} }
@ -1327,20 +1326,20 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
if (!inside_rx_window(header.sn)) { if (!inside_rx_window(header.sn)) {
if (header.p) { if (header.p) {
log->info("%s Status packet requested through polling bit\n", RB_NAME); logger.info("%s Status packet requested through polling bit", RB_NAME);
do_status = true; do_status = true;
} }
log->info("%s SN=%d outside rx window [%d:%d] - discarding\n", RB_NAME, header.sn, vr_r, vr_mr); logger.info("%s SN=%d outside rx window [%d:%d] - discarding", RB_NAME, header.sn, vr_r, vr_mr);
return; return;
} }
it = rx_window.find(header.sn); it = rx_window.find(header.sn);
if (rx_window.end() != it) { if (rx_window.end() != it) {
if (header.p) { if (header.p) {
log->info("%s Status packet requested through polling bit\n", RB_NAME); logger.info("%s Status packet requested through polling bit", RB_NAME);
do_status = true; do_status = true;
} }
log->info("%s Discarding duplicate SN=%d\n", RB_NAME, header.sn); logger.info("%s Discarding duplicate SN=%d", RB_NAME, header.sn);
return; return;
} }
@ -1352,7 +1351,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
srslte::console("Fatal Error: Couldn't allocate PDU in handle_data_pdu().\n"); srslte::console("Fatal Error: Couldn't allocate PDU in handle_data_pdu().\n");
exit(-1); exit(-1);
#else #else
log->error("Fatal Error: Couldn't allocate PDU in handle_data_pdu().\n"); logger.error("Fatal Error: Couldn't allocate PDU in handle_data_pdu().");
return; return;
#endif #endif
} }
@ -1360,7 +1359,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
// check available space for payload // check available space for payload
if (nof_bytes > pdu.buf->get_tailroom()) { if (nof_bytes > pdu.buf->get_tailroom()) {
log->error("%s Discarding SN=%d of size %d B (available space %d B)\n", logger.error("%s Discarding SN=%d of size %d B (available space %d B)",
RB_NAME, RB_NAME,
header.sn, header.sn,
nof_bytes, nof_bytes,
@ -1387,7 +1386,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
// Check poll bit // Check poll bit
if (header.p) { if (header.p) {
log->info("%s Status packet requested through polling bit\n", RB_NAME); logger.info("%s Status packet requested through polling bit", RB_NAME);
poll_received = true; poll_received = true;
// 36.322 v10 Section 5.2.3 // 36.322 v10 Section 5.2.3
@ -1404,21 +1403,21 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
if (reordering_timer.is_valid()) { if (reordering_timer.is_valid()) {
if (reordering_timer.is_running()) { if (reordering_timer.is_running()) {
if (vr_x == vr_r || (!inside_rx_window(vr_x) && vr_x != vr_mr)) { if (vr_x == vr_r || (!inside_rx_window(vr_x) && vr_x != vr_mr)) {
log->debug("Stopping reordering timer.\n"); logger.debug("Stopping reordering timer.");
reordering_timer.stop(); reordering_timer.stop();
} else { } else {
log->debug("Leave reordering timer running.\n"); logger.debug("Leave reordering timer running.");
} }
debug_state(); debug_state();
} }
if (not reordering_timer.is_running()) { if (not reordering_timer.is_running()) {
if (RX_MOD_BASE(vr_h) > RX_MOD_BASE(vr_r)) { if (RX_MOD_BASE(vr_h) > RX_MOD_BASE(vr_r)) {
log->debug("Starting reordering timer.\n"); logger.debug("Starting reordering timer.");
reordering_timer.run(); reordering_timer.run();
vr_x = vr_h; vr_x = vr_h;
} else { } else {
log->debug("Leave reordering timer stopped.\n"); logger.debug("Leave reordering timer stopped.");
} }
debug_state(); debug_state();
} }
@ -1433,7 +1432,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* pa
{ {
std::map<uint32_t, rlc_amd_rx_pdu_segments_t>::iterator it; std::map<uint32_t, rlc_amd_rx_pdu_segments_t>::iterator it;
log->info_hex(payload, logger.info(payload,
nof_bytes, nof_bytes,
"%s Rx data PDU segment of SN=%d (%d B), SO=%d, N_li=%d", "%s Rx data PDU segment of SN=%d (%d B), SO=%d, N_li=%d",
RB_NAME, RB_NAME,
@ -1441,15 +1440,15 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* pa
nof_bytes, nof_bytes,
header.so, header.so,
header.N_li); header.N_li);
log->debug("%s\n", rlc_amd_pdu_header_to_string(header).c_str()); logger.debug("%s", rlc_amd_pdu_header_to_string(header).c_str());
// Check inside rx window // Check inside rx window
if (!inside_rx_window(header.sn)) { if (!inside_rx_window(header.sn)) {
if (header.p) { if (header.p) {
log->info("%s Status packet requested through polling bit\n", RB_NAME); logger.info("%s Status packet requested through polling bit", RB_NAME);
do_status = true; do_status = true;
} }
log->info("%s SN=%d outside rx window [%d:%d] - discarding\n", RB_NAME, header.sn, vr_r, vr_mr); logger.info("%s SN=%d outside rx window [%d:%d] - discarding", RB_NAME, header.sn, vr_r, vr_mr);
return; return;
} }
@ -1460,13 +1459,13 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* pa
srslte::console("Fatal Error: Couldn't allocate PDU in handle_data_pdu_segment().\n"); srslte::console("Fatal Error: Couldn't allocate PDU in handle_data_pdu_segment().\n");
exit(-1); exit(-1);
#else #else
log->error("Fatal Error: Couldn't allocate PDU in handle_data_pdu_segment().\n"); logger.error("Fatal Error: Couldn't allocate PDU in handle_data_pdu_segment().");
return; return;
#endif #endif
} }
if (segment.buf->get_tailroom() < nof_bytes) { if (segment.buf->get_tailroom() < nof_bytes) {
log->info("Dropping corrupted segment SN=%d, not enough space to fit %d B\n", header.sn, nof_bytes); logger.info("Dropping corrupted segment SN=%d, not enough space to fit %d B", header.sn, nof_bytes);
return; return;
} }
@ -1478,7 +1477,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* pa
it = rx_segments.find(header.sn); it = rx_segments.find(header.sn);
if (rx_segments.end() != it) { if (rx_segments.end() != it) {
if (header.p) { if (header.p) {
log->info("%s Status packet requested through polling bit\n", RB_NAME); logger.info("%s Status packet requested through polling bit", RB_NAME);
do_status = true; do_status = true;
} }
@ -1501,7 +1500,7 @@ void rlc_am_lte::rlc_am_lte_rx::handle_data_pdu_segment(uint8_t* pa
// Check poll bit // Check poll bit
if (header.p) { if (header.p) {
log->info("%s Status packet requested through polling bit\n", RB_NAME); logger.info("%s Status packet requested through polling bit", RB_NAME);
poll_received = true; poll_received = true;
// 36.322 v10 Section 5.2.3 // 36.322 v10 Section 5.2.3
@ -1527,7 +1526,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus()
srslte::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (1)\n"); srslte::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (1)\n");
exit(-1); exit(-1);
#else #else
log->error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (1)\n"); logger.error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (1)");
return; return;
#endif #endif
} }
@ -1539,9 +1538,9 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus()
for (uint32_t i = 0; i < rx_window[vr_r].header.N_li; i++) { for (uint32_t i = 0; i < rx_window[vr_r].header.N_li; i++) {
len = rx_window[vr_r].header.li[i]; len = rx_window[vr_r].header.li[i];
log->debug_hex(rx_window[vr_r].buf->msg, logger.debug(rx_window[vr_r].buf->msg,
len, len,
"Handling segment %d/%d of length %d B of SN=%d\n", "Handling segment %d/%d of length %d B of SN=%d",
i + 1, i + 1,
rx_window[vr_r].header.N_li, rx_window[vr_r].header.N_li,
len, len,
@ -1555,7 +1554,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus()
if (rx_sdu->get_tailroom() >= len) { if (rx_sdu->get_tailroom() >= len) {
if ((rx_window[vr_r].buf->msg - rx_window[vr_r].buf->buffer) + len < SRSLTE_MAX_BUFFER_SIZE_BYTES) { if ((rx_window[vr_r].buf->msg - rx_window[vr_r].buf->buffer) + len < SRSLTE_MAX_BUFFER_SIZE_BYTES) {
if (rx_window[vr_r].buf->N_bytes < len) { if (rx_window[vr_r].buf->N_bytes < len) {
log->error("Dropping corrupted SN=%d\n", vr_r); logger.error("Dropping corrupted SN=%d", vr_r);
rx_sdu.reset(); rx_sdu.reset();
goto exit; goto exit;
} }
@ -1569,7 +1568,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus()
rx_window[vr_r].buf->msg += len; rx_window[vr_r].buf->msg += len;
rx_window[vr_r].buf->N_bytes -= len; rx_window[vr_r].buf->N_bytes -= len;
log->info_hex(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes); logger.info(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes);
sdu_rx_latency_ms.push(std::chrono::duration_cast<std::chrono::milliseconds>( sdu_rx_latency_ms.push(std::chrono::duration_cast<std::chrono::milliseconds>(
std::chrono::high_resolution_clock::now() - rx_sdu->get_timestamp()) std::chrono::high_resolution_clock::now() - rx_sdu->get_timestamp())
.count()); .count());
@ -1582,18 +1581,18 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus()
srslte::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (2)\n"); srslte::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (2)\n");
exit(-1); exit(-1);
#else #else
log->error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (2)\n"); logger.error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (2)");
return; return;
#endif #endif
} }
} else { } else {
int buf_len = rx_window[vr_r].buf->msg - rx_window[vr_r].buf->buffer; int buf_len = rx_window[vr_r].buf->msg - rx_window[vr_r].buf->buffer;
log->error("Cannot read %d bytes from rx_window. vr_r=%d, msg-buffer=%d B\n", len, vr_r, buf_len); logger.error("Cannot read %d bytes from rx_window. vr_r=%d, msg-buffer=%d B", len, vr_r, buf_len);
rx_sdu.reset(); rx_sdu.reset();
goto exit; goto exit;
} }
} else { } else {
log->error("Cannot fit RLC PDU in SDU buffer, dropping both.\n"); logger.error("Cannot fit RLC PDU in SDU buffer, dropping both.");
rx_sdu.reset(); rx_sdu.reset();
goto exit; goto exit;
} }
@ -1601,7 +1600,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus()
// Handle last segment // Handle last segment
len = rx_window[vr_r].buf->N_bytes; len = rx_window[vr_r].buf->N_bytes;
log->debug_hex(rx_window[vr_r].buf->msg, len, "Handling last segment of length %d B of SN=%d\n", len, vr_r); logger.debug(rx_window[vr_r].buf->msg, len, "Handling last segment of length %d B of SN=%d", len, vr_r);
if (rx_sdu->get_tailroom() >= len) { if (rx_sdu->get_tailroom() >= len) {
// store timestamp of the first segment when starting to assemble SDUs // store timestamp of the first segment when starting to assemble SDUs
if (rx_sdu->N_bytes == 0) { if (rx_sdu->N_bytes == 0) {
@ -1619,7 +1618,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus()
} }
if (rlc_am_end_aligned(rx_window[vr_r].header.fi)) { if (rlc_am_end_aligned(rx_window[vr_r].header.fi)) {
log->info_hex(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes); logger.info(rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU (%d B)", RB_NAME, rx_sdu->N_bytes);
sdu_rx_latency_ms.push(std::chrono::duration_cast<std::chrono::milliseconds>( sdu_rx_latency_ms.push(std::chrono::duration_cast<std::chrono::milliseconds>(
std::chrono::high_resolution_clock::now() - rx_sdu->get_timestamp()) std::chrono::high_resolution_clock::now() - rx_sdu->get_timestamp())
.count()); .count());
@ -1632,7 +1631,7 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus()
srslte::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (3)\n"); srslte::console("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (3)\n");
exit(-1); exit(-1);
#else #else
log->error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (3)\n"); logger.error("Fatal Error: Could not allocate PDU in reassemble_rx_sdus() (3)");
return; return;
#endif #endif
} }
@ -1640,15 +1639,15 @@ void rlc_am_lte::rlc_am_lte_rx::reassemble_rx_sdus()
exit: exit:
// Move the rx_window // Move the rx_window
log->debug("Erasing SN=%d.\n", vr_r); logger.debug("Erasing SN=%d.", vr_r);
// also erase any segments of this SN // also erase any segments of this SN
std::map<uint32_t, rlc_amd_rx_pdu_segments_t>::iterator it; std::map<uint32_t, rlc_amd_rx_pdu_segments_t>::iterator it;
it = rx_segments.find(vr_r); it = rx_segments.find(vr_r);
if (rx_segments.end() != it) { if (rx_segments.end() != it) {
log->debug("Erasing segments of SN=%d\n", vr_r); logger.debug("Erasing segments of SN=%d", vr_r);
std::list<rlc_amd_rx_pdu_t>::iterator segit; std::list<rlc_amd_rx_pdu_t>::iterator segit;
for (segit = it->second.segments.begin(); segit != it->second.segments.end(); ++segit) { for (segit = it->second.segments.begin(); segit != it->second.segments.end(); ++segit) {
log->debug(" Erasing segment of SN=%d SO=%d Len=%d N_li=%d\n", logger.debug(" Erasing segment of SN=%d SO=%d Len=%d N_li=%d",
segit->header.sn, segit->header.sn,
segit->header.so, segit->header.so,
segit->buf->N_bytes, segit->buf->N_bytes,
@ -1691,7 +1690,7 @@ void rlc_am_lte::rlc_am_lte_rx::write_pdu(uint8_t* payload, const uint32_t nof_b
uint32_t payload_len = nof_bytes; uint32_t payload_len = nof_bytes;
rlc_am_read_data_pdu_header(&payload, &payload_len, &header); rlc_am_read_data_pdu_header(&payload, &payload_len, &header);
if (payload_len > nof_bytes) { if (payload_len > nof_bytes) {
log->info("Dropping corrupted PDU (%d B). Remaining length after header %d B.\n", nof_bytes, payload_len); logger.info("Dropping corrupted PDU (%d B). Remaining length after header %d B.", nof_bytes, payload_len);
pthread_mutex_unlock(&mutex); pthread_mutex_unlock(&mutex);
return; return;
} }
@ -1733,7 +1732,7 @@ void rlc_am_lte::rlc_am_lte_rx::timer_expired(uint32_t timeout_id)
{ {
pthread_mutex_lock(&mutex); pthread_mutex_lock(&mutex);
if (reordering_timer.is_valid() and reordering_timer.id() == timeout_id) { if (reordering_timer.is_valid() and reordering_timer.id() == timeout_id) {
log->debug("%s reordering timeout expiry - updating vr_ms (was %d)\n", RB_NAME, vr_ms); logger.debug("%s reordering timeout expiry - updating vr_ms (was %d)", RB_NAME, vr_ms);
// 36.322 v10 Section 5.1.3.2.4 // 36.322 v10 Section 5.1.3.2.4
vr_ms = vr_x; vr_ms = vr_x;
@ -1777,18 +1776,18 @@ int rlc_am_lte::rlc_am_lte_rx::get_status_pdu(rlc_status_pdu_t* status, const ui
// make sure we don't exceed grant size // make sure we don't exceed grant size
if (rlc_am_packed_length(status) > max_pdu_size) { if (rlc_am_packed_length(status) > max_pdu_size) {
log->debug("Status PDU too big (%d > %d)\n", rlc_am_packed_length(status), max_pdu_size); logger.debug("Status PDU too big (%d > %d)", rlc_am_packed_length(status), max_pdu_size);
if (status->N_nack >= 1 && status->N_nack < RLC_AM_WINDOW_SIZE) { if (status->N_nack >= 1 && status->N_nack < RLC_AM_WINDOW_SIZE) {
log->debug("Removing last NACK SN=%d\n", status->nacks[status->N_nack].nack_sn); logger.debug("Removing last NACK SN=%d", status->nacks[status->N_nack].nack_sn);
status->N_nack--; status->N_nack--;
// make sure we don't have the current ACK_SN in the NACK list // make sure we don't have the current ACK_SN in the NACK list
if (rlc_am_is_valid_status_pdu(*status) == false) { if (rlc_am_is_valid_status_pdu(*status) == false) {
// No space to send any NACKs // No space to send any NACKs
log->debug("Resetting N_nack to zero\n"); logger.debug("Resetting N_nack to zero");
status->N_nack = 0; status->N_nack = 0;
} }
} else { } else {
log->warning("Failed to generate small enough status PDU (packed_len=%d, max_pdu_size=%d, status->N_nack=%d)\n", logger.warning("Failed to generate small enough status PDU (packed_len=%d, max_pdu_size=%d, status->N_nack=%d)",
rlc_am_packed_length(status), rlc_am_packed_length(status),
max_pdu_size, max_pdu_size,
status->N_nack); status->N_nack);
@ -1831,7 +1830,7 @@ void rlc_am_lte::rlc_am_lte_rx::print_rx_segments()
<< " N_li: " << segit->header.N_li << std::endl; << " N_li: " << segit->header.N_li << std::endl;
} }
} }
log->debug("%s\n", ss.str().c_str()); logger.debug("%s", ss.str().c_str());
} }
// NOTE: Preference would be to capture by value, and then move; but header is stack allocated // NOTE: Preference would be to capture by value, and then move; but header is stack allocated
@ -1905,19 +1904,19 @@ bool rlc_am_lte::rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t*
header.fi |= (pdu->segments.front().header.fi & RLC_FI_FIELD_NOT_START_ALIGNED); header.fi |= (pdu->segments.front().header.fi & RLC_FI_FIELD_NOT_START_ALIGNED);
header.fi |= (pdu->segments.back().header.fi & RLC_FI_FIELD_NOT_END_ALIGNED); header.fi |= (pdu->segments.back().header.fi & RLC_FI_FIELD_NOT_END_ALIGNED);
log->debug("Starting header reconstruction of %zd segments\n", pdu->segments.size()); logger.debug("Starting header reconstruction of %zd segments", pdu->segments.size());
// Reconstruct li fields // Reconstruct li fields
uint16_t count = 0; uint16_t count = 0;
uint16_t carryover = 0; uint16_t carryover = 0;
for (it = pdu->segments.begin(); it != pdu->segments.end(); it++) { for (it = pdu->segments.begin(); it != pdu->segments.end(); it++) {
log->debug(" Handling %d PDU segments\n", it->header.N_li); logger.debug(" Handling %d PDU segments", it->header.N_li);
for (uint32_t i = 0; i < it->header.N_li; i++) { for (uint32_t i = 0; i < it->header.N_li; i++) {
header.li[header.N_li] = it->header.li[i]; header.li[header.N_li] = it->header.li[i];
if (i == 0) { if (i == 0) {
header.li[header.N_li] += carryover; header.li[header.N_li] += carryover;
} }
log->debug(" - adding segment %d/%d (%d B, SO=%d, carryover=%d, count=%d)\n", logger.debug(" - adding segment %d/%d (%d B, SO=%d, carryover=%d, count=%d)",
i + 1, i + 1,
it->header.N_li, it->header.N_li,
header.li[header.N_li], header.li[header.N_li],
@ -1931,7 +1930,7 @@ bool rlc_am_lte::rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t*
if (count <= it->buf->N_bytes) { if (count <= it->buf->N_bytes) {
carryover += it->buf->N_bytes - count; carryover += it->buf->N_bytes - count;
log->debug("Incremented carryover (it->buf->N_bytes=%d, count=%d). New carryover=%d\n", logger.debug("Incremented carryover (it->buf->N_bytes=%d, count=%d). New carryover=%d",
it->buf->N_bytes, it->buf->N_bytes,
count, count,
carryover); carryover);
@ -1939,7 +1938,7 @@ bool rlc_am_lte::rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t*
// Next segment would be too long, recalculate carryover // Next segment would be too long, recalculate carryover
header.N_li--; header.N_li--;
carryover = it->buf->N_bytes - (count - header.li[header.N_li]); carryover = it->buf->N_bytes - (count - header.li[header.N_li]);
log->debug("Recalculated carryover=%d (it->buf->N_bytes=%d, count=%d, header.li[header.N_li]=%d)\n", logger.debug("Recalculated carryover=%d (it->buf->N_bytes=%d, count=%d, header.li[header.N_li]=%d)",
carryover, carryover,
it->buf->N_bytes, it->buf->N_bytes,
count, count,
@ -1948,7 +1947,7 @@ bool rlc_am_lte::rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t*
tmpit = it; tmpit = it;
if (rlc_am_end_aligned(it->header.fi) && ++tmpit != pdu->segments.end()) { if (rlc_am_end_aligned(it->header.fi) && ++tmpit != pdu->segments.end()) {
log->debug("Header is end-aligned, overwrite header.li[%d]=%d\n", header.N_li, carryover); logger.debug("Header is end-aligned, overwrite header.li[%d]=%d", header.N_li, carryover);
header.li[header.N_li] = carryover; header.li[header.N_li] = carryover;
header.N_li++; header.N_li++;
carryover = 0; carryover = 0;
@ -1959,7 +1958,7 @@ bool rlc_am_lte::rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t*
header.p |= it->header.p; header.p |= it->header.p;
} }
log->debug("Finished header reconstruction of %zd segments\n", pdu->segments.size()); logger.debug("Finished header reconstruction of %zd segments", pdu->segments.size());
// Copy data // Copy data
unique_byte_buffer_t full_pdu = srslte::make_byte_buffer(); unique_byte_buffer_t full_pdu = srslte::make_byte_buffer();
@ -1968,7 +1967,7 @@ bool rlc_am_lte::rlc_am_lte_rx::add_segment_and_check(rlc_amd_rx_pdu_segments_t*
srslte::console("Fatal Error: Could not allocate PDU in add_segment_and_check()\n"); srslte::console("Fatal Error: Could not allocate PDU in add_segment_and_check()\n");
exit(-1); exit(-1);
#else #else
log->error("Fatal Error: Could not allocate PDU in add_segment_and_check()\n"); logger.error("Fatal Error: Could not allocate PDU in add_segment_and_check()");
return false; return false;
#endif #endif
} }
@ -2004,7 +2003,7 @@ bool rlc_am_lte::rlc_am_lte_rx::inside_rx_window(const int16_t sn)
void rlc_am_lte::rlc_am_lte_rx::debug_state() void rlc_am_lte::rlc_am_lte_rx::debug_state()
{ {
log->debug("%s vr_r = %d, vr_mr = %d, vr_x = %d, vr_ms = %d, vr_h = %d\n", RB_NAME, vr_r, vr_mr, vr_x, vr_ms, vr_h); logger.debug("%s vr_r = %d, vr_mr = %d, vr_x = %d, vr_ms = %d, vr_h = %d", RB_NAME, vr_r, vr_mr, vr_x, vr_ms, vr_h);
} }
/**************************************************************************** /****************************************************************************

31
lib/src/upper/rlc_tm.cc
Unescape Escape View File

@ -14,8 +14,11 @@
namespace srslte { namespace srslte {
rlc_tm::rlc_tm(srslte::log_ref log_, uint32_t lcid_, srsue::pdcp_interface_rlc* pdcp_, srsue::rrc_interface_rlc* rrc_) : rlc_tm::rlc_tm(srslog::basic_logger& logger,
log(log_), pdcp(pdcp_), rrc(rrc_), lcid(lcid_) uint32_t lcid_,
srsue::pdcp_interface_rlc* pdcp_,
srsue::rrc_interface_rlc* rrc_) :
logger(logger), pdcp(pdcp_), rrc(rrc_), lcid(lcid_)
{ {
pool = byte_buffer_pool::get_instance(); pool = byte_buffer_pool::get_instance();
} }
@ -28,7 +31,7 @@ rlc_tm::~rlc_tm()
bool rlc_tm::configure(const rlc_config_t& cnfg) bool rlc_tm::configure(const rlc_config_t& cnfg)
{ {
log->error("Attempted to configure TM RLC entity\n"); logger.error("Attempted to configure TM RLC entity");
return true; return true;
} }
@ -74,14 +77,14 @@ void rlc_tm::write_sdu(unique_byte_buffer_t sdu)
uint32_t nof_bytes = sdu->N_bytes; uint32_t nof_bytes = sdu->N_bytes;
srslte::error_type<unique_byte_buffer_t> ret = ul_queue.try_write(std::move(sdu)); srslte::error_type<unique_byte_buffer_t> ret = ul_queue.try_write(std::move(sdu));
if (ret) { if (ret) {
log->info_hex(msg_ptr, logger.info(msg_ptr,
nof_bytes, nof_bytes,
"%s Tx SDU, queue size=%d, bytes=%d", "%s Tx SDU, queue size=%d, bytes=%d",
rrc->get_rb_name(lcid).c_str(), rrc->get_rb_name(lcid).c_str(),
ul_queue.size(), ul_queue.size(),
ul_queue.size_bytes()); ul_queue.size_bytes());
} else { } else {
log->warning_hex(ret.error()->msg, logger.warning(ret.error()->msg,
ret.error()->N_bytes, ret.error()->N_bytes,
"[Dropped SDU] %s Tx SDU, queue size=%d, bytes=%d", "[Dropped SDU] %s Tx SDU, queue size=%d, bytes=%d",
rrc->get_rb_name(lcid).c_str(), rrc->get_rb_name(lcid).c_str(),
@ -90,7 +93,7 @@ void rlc_tm::write_sdu(unique_byte_buffer_t sdu)
} }
} else { } else {
log->warning("NULL SDU pointer in write_sdu()\n"); logger.warning("NULL SDU pointer in write_sdu()");
} }
} }
@ -99,7 +102,7 @@ void rlc_tm::discard_sdu(uint32_t discard_sn)
if (!tx_enabled) { if (!tx_enabled) {
return; return;
} }
log->warning("SDU discard not implemented on RLC TM\n"); logger.warning("SDU discard not implemented on RLC TM");
} }
bool rlc_tm::sdu_queue_is_full() bool rlc_tm::sdu_queue_is_full()
@ -132,18 +135,18 @@ int rlc_tm::read_pdu(uint8_t* payload, uint32_t nof_bytes)
{ {
uint32_t pdu_size = ul_queue.size_tail_bytes(); uint32_t pdu_size = ul_queue.size_tail_bytes();
if (pdu_size > nof_bytes) { if (pdu_size > nof_bytes) {
log->info( logger.info(
"%s Tx PDU size larger than MAC opportunity (%d > %d)\n", rrc->get_rb_name(lcid).c_str(), pdu_size, nof_bytes); "%s Tx PDU size larger than MAC opportunity (%d > %d)", rrc->get_rb_name(lcid).c_str(), pdu_size, nof_bytes);
return -1; return -1;
} }
unique_byte_buffer_t buf; unique_byte_buffer_t buf;
if (ul_queue.try_read(&buf)) { if (ul_queue.try_read(&buf)) {
pdu_size = buf->N_bytes; pdu_size = buf->N_bytes;
memcpy(payload, buf->msg, buf->N_bytes); memcpy(payload, buf->msg, buf->N_bytes);
log->debug("%s Complete SDU scheduled for tx. Stack latency: %" PRIu64 " us\n", logger.debug("%s Complete SDU scheduled for tx. Stack latency: %" PRIu64 " us",
rrc->get_rb_name(lcid).c_str(), rrc->get_rb_name(lcid).c_str(),
(uint64_t)buf->get_latency_us().count()); (uint64_t)buf->get_latency_us().count());
log->info_hex(payload, logger.info(payload,
pdu_size, pdu_size,
"%s Tx %s PDU, queue size=%d, bytes=%d", "%s Tx %s PDU, queue size=%d, bytes=%d",
rrc->get_rb_name(lcid).c_str(), rrc->get_rb_name(lcid).c_str(),
@ -154,9 +157,9 @@ int rlc_tm::read_pdu(uint8_t* payload, uint32_t nof_bytes)
metrics.num_tx_pdu_bytes += pdu_size; metrics.num_tx_pdu_bytes += pdu_size;
return pdu_size; return pdu_size;
} else { } else {
log->warning("Queue empty while trying to read\n"); logger.warning("Queue empty while trying to read");
if (ul_queue.size_bytes() > 0) { if (ul_queue.size_bytes() > 0) {
log->warning("Corrupted queue: empty but size_bytes > 0. Resetting queue\n"); logger.warning("Corrupted queue: empty but size_bytes > 0. Resetting queue");
ul_queue.reset(); ul_queue.reset();
} }
return 0; return 0;
@ -178,7 +181,7 @@ void rlc_tm::write_pdu(uint8_t* payload, uint32_t nof_bytes)
pdcp->write_pdu(lcid, std::move(buf)); pdcp->write_pdu(lcid, std::move(buf));
} }
} else { } else {
log->error("Fatal Error: Couldn't allocate buffer in rlc_tm::write_pdu().\n"); logger.error("Fatal Error: Couldn't allocate buffer in rlc_tm::write_pdu().");
} }
} }

30
lib/src/upper/rlc_um_base.cc
Unescape Escape View File

@ -15,12 +15,12 @@
namespace srslte { namespace srslte {
rlc_um_base::rlc_um_base(srslte::log_ref log_, rlc_um_base::rlc_um_base(srslog::basic_logger& logger,
uint32_t lcid_, uint32_t lcid_,
srsue::pdcp_interface_rlc* pdcp_, srsue::pdcp_interface_rlc* pdcp_,
srsue::rrc_interface_rlc* rrc_, srsue::rrc_interface_rlc* rrc_,
srslte::timer_handler* timers_) : srslte::timer_handler* timers_) :
log(log_), lcid(lcid_), pdcp(pdcp_), rrc(rrc_), timers(timers_), pool(byte_buffer_pool::get_instance()) logger(logger), lcid(lcid_), pdcp(pdcp_), rrc(rrc_), timers(timers_), pool(byte_buffer_pool::get_instance())
{} {}
rlc_um_base::~rlc_um_base() {} rlc_um_base::~rlc_um_base() {}
@ -80,7 +80,7 @@ void rlc_um_base::empty_queue()
void rlc_um_base::write_sdu(unique_byte_buffer_t sdu) void rlc_um_base::write_sdu(unique_byte_buffer_t sdu)
{ {
if (not tx_enabled || not tx) { if (not tx_enabled || not tx) {
log->debug("%s is currently deactivated. Dropping SDU (%d B)\n", rb_name.c_str(), sdu->N_bytes); logger.debug("%s is currently deactivated. Dropping SDU (%d B)", rb_name.c_str(), sdu->N_bytes);
metrics.num_lost_sdus++; metrics.num_lost_sdus++;
return; return;
} }
@ -97,7 +97,7 @@ void rlc_um_base::write_sdu(unique_byte_buffer_t sdu)
void rlc_um_base::discard_sdu(uint32_t discard_sn) void rlc_um_base::discard_sdu(uint32_t discard_sn)
{ {
if (not tx_enabled || not tx) { if (not tx_enabled || not tx) {
log->debug("%s is currently deactivated. Ignoring SDU discard (SN=%u)\n", rb_name.c_str(), discard_sn); logger.debug("%s is currently deactivated. Ignoring SDU discard (SN=%u)", rb_name.c_str(), discard_sn);
return; return;
} }
tx->discard_sdu(discard_sn); tx->discard_sdu(discard_sn);
@ -182,7 +182,7 @@ std::string rlc_um_base::get_rb_name(srsue::rrc_interface_rlc* rrc, uint32_t lci
rlc_um_base::rlc_um_base_rx::rlc_um_base_rx(rlc_um_base* parent_) : rlc_um_base::rlc_um_base_rx::rlc_um_base_rx(rlc_um_base* parent_) :
pool(parent_->pool), pool(parent_->pool),
log(parent_->log), logger(parent_->logger),
timers(parent_->timers), timers(parent_->timers),
pdcp(parent_->pdcp), pdcp(parent_->pdcp),
rrc(parent_->rrc), rrc(parent_->rrc),
@ -198,7 +198,7 @@ rlc_um_base::rlc_um_base_rx::~rlc_um_base_rx() {}
***************************************************************************/ ***************************************************************************/
rlc_um_base::rlc_um_base_tx::rlc_um_base_tx(rlc_um_base* parent_) : rlc_um_base::rlc_um_base_tx::rlc_um_base_tx(rlc_um_base* parent_) :
log(parent_->log), pool(parent_->pool), parent(parent_) logger(parent_->logger), pool(parent_->pool), parent(parent_)
{} {}
rlc_um_base::rlc_um_base_tx::~rlc_um_base_tx() {} rlc_um_base::rlc_um_base_tx::~rlc_um_base_tx() {}
@ -236,7 +236,7 @@ bool rlc_um_base::rlc_um_base_tx::has_data()
void rlc_um_base::rlc_um_base_tx::write_sdu(unique_byte_buffer_t sdu) void rlc_um_base::rlc_um_base_tx::write_sdu(unique_byte_buffer_t sdu)
{ {
if (sdu) { if (sdu) {
log->info_hex(sdu->msg, logger.info(sdu->msg,
sdu->N_bytes, sdu->N_bytes,
"%s Tx SDU (%d B, tx_sdu_queue_len=%d)", "%s Tx SDU (%d B, tx_sdu_queue_len=%d)",
rb_name.c_str(), rb_name.c_str(),
@ -244,7 +244,7 @@ void rlc_um_base::rlc_um_base_tx::write_sdu(unique_byte_buffer_t sdu)
tx_sdu_queue.size()); tx_sdu_queue.size());
tx_sdu_queue.write(std::move(sdu)); tx_sdu_queue.write(std::move(sdu));
} else { } else {
log->warning("NULL SDU pointer in write_sdu()\n"); logger.warning("NULL SDU pointer in write_sdu()");
} }
} }
@ -255,11 +255,11 @@ int rlc_um_base::rlc_um_base_tx::try_write_sdu(unique_byte_buffer_t sdu)
uint32_t nof_bytes = sdu->N_bytes; uint32_t nof_bytes = sdu->N_bytes;
srslte::error_type<unique_byte_buffer_t> ret = tx_sdu_queue.try_write(std::move(sdu)); srslte::error_type<unique_byte_buffer_t> ret = tx_sdu_queue.try_write(std::move(sdu));
if (ret) { if (ret) {
log->info_hex( logger.info(
msg_ptr, nof_bytes, "%s Tx SDU (%d B, tx_sdu_queue_len=%d)", rb_name.c_str(), nof_bytes, tx_sdu_queue.size()); msg_ptr, nof_bytes, "%s Tx SDU (%d B, tx_sdu_queue_len=%d)", rb_name.c_str(), nof_bytes, tx_sdu_queue.size());
return SRSLTE_SUCCESS; return SRSLTE_SUCCESS;
} else { } else {
log->warning_hex(ret.error()->msg, logger.warning(ret.error()->msg,
ret.error()->N_bytes, ret.error()->N_bytes,
"[Dropped SDU] %s Tx SDU (%d B, tx_sdu_queue_len=%d)", "[Dropped SDU] %s Tx SDU (%d B, tx_sdu_queue_len=%d)",
rb_name.c_str(), rb_name.c_str(),
@ -267,14 +267,14 @@ int rlc_um_base::rlc_um_base_tx::try_write_sdu(unique_byte_buffer_t sdu)
tx_sdu_queue.size()); tx_sdu_queue.size());
} }
} else { } else {
log->warning("NULL SDU pointer in write_sdu()\n"); logger.warning("NULL SDU pointer in write_sdu()");
} }
return SRSLTE_ERROR; return SRSLTE_ERROR;
} }
void rlc_um_base::rlc_um_base_tx::discard_sdu(uint32_t discard_sn) void rlc_um_base::rlc_um_base_tx::discard_sdu(uint32_t discard_sn)
{ {
log->warning("RLC UM: Discard SDU not implemented yet.\n"); logger.warning("RLC UM: Discard SDU not implemented yet.");
} }
bool rlc_um_base::rlc_um_base_tx::sdu_queue_is_full() bool rlc_um_base::rlc_um_base_tx::sdu_queue_is_full()
@ -287,16 +287,16 @@ int rlc_um_base::rlc_um_base_tx::build_data_pdu(uint8_t* payload, uint32_t nof_b
unique_byte_buffer_t pdu; unique_byte_buffer_t pdu;
{ {
std::lock_guard<std::mutex> lock(mutex); std::lock_guard<std::mutex> lock(mutex);
log->debug("MAC opportunity - %d bytes\n", nof_bytes); logger.debug("MAC opportunity - %d bytes", nof_bytes);
if (tx_sdu == nullptr && tx_sdu_queue.is_empty()) { if (tx_sdu == nullptr && tx_sdu_queue.is_empty()) {
log->info("No data available to be sent\n"); logger.info("No data available to be sent");
return 0; return 0;
} }
pdu = make_byte_buffer(); pdu = make_byte_buffer();
if (!pdu || pdu->N_bytes != 0) { if (!pdu || pdu->N_bytes != 0) {
log->error("Failed to allocate PDU buffer\n"); logger.error("Failed to allocate PDU buffer");
return 0; return 0;
} }
} }

126
lib/src/upper/rlc_um_lte.cc
Unescape Escape View File

@ -17,12 +17,12 @@
namespace srslte { namespace srslte {
rlc_um_lte::rlc_um_lte(srslte::log_ref log_, rlc_um_lte::rlc_um_lte(srslog::basic_logger& logger,
uint32_t lcid_, uint32_t lcid_,
srsue::pdcp_interface_rlc* pdcp_, srsue::pdcp_interface_rlc* pdcp_,
srsue::rrc_interface_rlc* rrc_, srsue::rrc_interface_rlc* rrc_,
srslte::timer_handler* timers_) : srslte::timer_handler* timers_) :
rlc_um_base(log_, lcid_, pdcp_, rrc_, timers_) rlc_um_base(logger, lcid_, pdcp_, rrc_, timers_)
{} {}
// Warning: must call stop() to properly deallocate all buffers // Warning: must call stop() to properly deallocate all buffers
@ -49,7 +49,7 @@ bool rlc_um_lte::configure(const rlc_config_t& cnfg_)
return false; return false;
} }
log->info("%s configured in %s: t_reordering=%d ms, rx_sn_field_length=%u bits, tx_sn_field_length=%u bits\n", logger.info("%s configured in %s: t_reordering=%d ms, rx_sn_field_length=%u bits, tx_sn_field_length=%u bits",
rb_name.c_str(), rb_name.c_str(),
srslte::to_string(cnfg_.rlc_mode).c_str(), srslte::to_string(cnfg_.rlc_mode).c_str(),
cfg.um.t_reordering, cfg.um.t_reordering,
@ -97,7 +97,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) {
log->error("Error configuring %s RLC UM: tx_mod==0\n", rb_name.c_str()); logger.error("Error configuring %s RLC UM: tx_mod==0", rb_name.c_str());
return false; return false;
} }
@ -125,7 +125,7 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
int pdu_space = SRSLTE_MIN(nof_bytes, pdu->get_tailroom()); int pdu_space = SRSLTE_MIN(nof_bytes, pdu->get_tailroom());
if (pdu_space <= head_len + 1) { if (pdu_space <= head_len + 1) {
log->info("%s Cannot build a PDU - %d bytes available, %d bytes required for header\n", logger.info("%s Cannot build a PDU - %d bytes available, %d bytes required for header",
rb_name.c_str(), rb_name.c_str(),
nof_bytes, nof_bytes,
head_len); head_len);
@ -136,8 +136,8 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
if (tx_sdu) { 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;
log->debug( logger.debug(
"%s adding remainder of SDU segment - %d bytes of %d remaining\n", rb_name.c_str(), 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;
@ -148,12 +148,12 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
#ifdef ENABLE_TIMESTAMP #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);
log->debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us\n", logger.debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us",
rb_name.c_str(), 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
log->debug("%s Complete SDU scheduled for tx.\n", rb_name.c_str()); logger.debug("%s Complete SDU scheduled for tx.", rb_name.c_str());
#endif #endif
tx_sdu.reset(); tx_sdu.reset();
} }
@ -163,7 +163,7 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
// Pull SDUs from queue // 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) {
log->debug("pdu_space=%d, head_len=%d\n", pdu_space, head_len); logger.debug("pdu_space=%d, head_len=%d", pdu_space, head_len);
if (last_li > 0) { if (last_li > 0) {
header.li[header.N_li++] = last_li; header.li[header.N_li++] = last_li;
} }
@ -176,7 +176,7 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
} }
tx_sdu = tx_sdu_queue.read(); 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;
log->debug("%s adding new SDU segment - %d bytes of %d remaining\n", rb_name.c_str(), to_move, tx_sdu->N_bytes); logger.debug("%s adding new SDU segment - %d bytes of %d remaining", rb_name.c_str(), to_move, tx_sdu->N_bytes);
memcpy(pdu_ptr, tx_sdu->msg, to_move); memcpy(pdu_ptr, tx_sdu->msg, to_move);
last_li = to_move; last_li = to_move;
pdu_ptr += to_move; pdu_ptr += to_move;
@ -187,12 +187,12 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
#ifdef ENABLE_TIMESTAMP #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);
log->debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us\n", logger.debug("%s Complete SDU scheduled for tx. Stack latency (last/average): %" PRIu64 "/%ld us",
rb_name.c_str(), 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
log->debug("%s Complete SDU scheduled for tx.\n", rb_name.c_str()); logger.debug("%s Complete SDU scheduled for tx.", rb_name.c_str());
#endif #endif
tx_sdu.reset(); tx_sdu.reset();
} }
@ -211,7 +211,7 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
rlc_um_write_data_pdu_header(&header, pdu.get()); rlc_um_write_data_pdu_header(&header, pdu.get());
memcpy(payload, pdu->msg, pdu->N_bytes); memcpy(payload, pdu->msg, pdu->N_bytes);
log->info_hex(payload, pdu->N_bytes, "%s Tx PDU SN=%d (%d B)\n", rb_name.c_str(), header.sn, pdu->N_bytes); logger.info(payload, pdu->N_bytes, "%s Tx PDU SN=%d (%d B)", rb_name.c_str(), header.sn, pdu->N_bytes);
debug_state(); debug_state();
@ -220,7 +220,7 @@ int rlc_um_lte::rlc_um_lte_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t*
void rlc_um_lte::rlc_um_lte_tx::debug_state() void rlc_um_lte::rlc_um_lte_tx::debug_state()
{ {
log->debug("%s vt_us = %d\n", rb_name.c_str(), vt_us); logger.debug("%s vt_us = %d", rb_name.c_str(), vt_us);
} }
void rlc_um_lte::rlc_um_lte_tx::reset() void rlc_um_lte::rlc_um_lte_tx::reset()
@ -243,13 +243,13 @@ bool rlc_um_lte::rlc_um_lte_rx::configure(const rlc_config_t& cnfg_, std::string
cfg = cnfg_; cfg = cnfg_;
if (cfg.um.rx_mod == 0) { if (cfg.um.rx_mod == 0) {
log->error("Error configuring %s RLC UM: rx_mod==0\n", rb_name.c_str()); logger.error("Error configuring %s RLC UM: rx_mod==0", rb_name.c_str());
return false; return false;
} }
// check timer // check timer
if (not reordering_timer.is_valid()) { if (not reordering_timer.is_valid()) {
log->error("Configuring RLC UM RX: timers not configured\n"); logger.error("Configuring RLC UM RX: timers not configured");
return false; return false;
} }
@ -298,17 +298,17 @@ void rlc_um_lte::rlc_um_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
{ {
rlc_umd_pdu_header_t header; rlc_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);
log->info_hex(payload, nof_bytes, "%s Rx data PDU SN=%d (%d B)", rb_name.c_str(), header.sn, nof_bytes); logger.info(payload, nof_bytes, "%s Rx data PDU SN=%d (%d B)", rb_name.c_str(), header.sn, nof_bytes);
if (RX_MOD_BASE(header.sn) >= RX_MOD_BASE(vr_uh - cfg.um.rx_window_size) && 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)) {
log->info("%s SN=%d outside rx window [%d:%d] - discarding\n", rb_name.c_str(), header.sn, vr_ur, vr_uh); logger.info("%s SN=%d outside rx window [%d:%d] - discarding", rb_name.c_str(), header.sn, vr_ur, vr_uh);
return; 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) {
log->info("%s Discarding duplicate SN=%d\n", rb_name.c_str(), header.sn); logger.info("%s Discarding duplicate SN=%d", rb_name.c_str(), header.sn);
return; return;
} }
@ -316,7 +316,7 @@ void rlc_um_lte::rlc_um_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
rlc_umd_pdu_t pdu = {}; rlc_umd_pdu_t pdu = {};
pdu.buf = make_byte_buffer(); pdu.buf = make_byte_buffer();
if (!pdu.buf) { if (!pdu.buf) {
log->error("Discarting packet: no space in buffer pool\n"); logger.error("Discarting packet: no space in buffer pool");
return; return;
} }
memcpy(pdu.buf->msg, payload, nof_bytes); memcpy(pdu.buf->msg, payload, nof_bytes);
@ -334,9 +334,9 @@ void rlc_um_lte::rlc_um_lte_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_b
} }
// Reassemble and deliver SDUs, while updating vr_ur // Reassemble and deliver SDUs, while updating vr_ur
log->debug("Entering Reassemble from received PDU\n"); logger.debug("Entering Reassemble from received PDU");
reassemble_rx_sdus(); reassemble_rx_sdus();
log->debug("Finished reassemble from received PDU\n"); logger.debug("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()) {
@ -360,32 +360,32 @@ 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) {
log->error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().\n"); logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().");
return; 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)) {
log->debug("SN=%d is not inside reordering windows\n", vr_ur); logger.debug("SN=%d is not inside reordering windows", vr_ur);
if (rx_window.end() == rx_window.find(vr_ur)) { if (rx_window.end() == rx_window.find(vr_ur)) {
log->debug("SN=%d not in rx_window. Reset received SDU\n", vr_ur); logger.debug("SN=%d not in rx_window. Reset received SDU", vr_ur);
rx_sdu->clear(); 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];
log->debug_hex(rx_window[vr_ur].buf->msg, logger.debug(rx_window[vr_ur].buf->msg,
len, len,
"Handling segment %d/%d of length %d B of SN=%d\n", "Handling segment %d/%d of length %d B of SN=%d",
i + 1, i + 1,
rx_window[vr_ur].header.N_li, rx_window[vr_ur].header.N_li,
len, len,
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)) {
log->warning("Dropping PDU %d in reassembly due to lost start segment\n", vr_ur); logger.warning("Dropping PDU %d in reassembly due to lost start segment", vr_ur);
// Advance data pointers and continue with next segment // 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;
@ -400,13 +400,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))) {
log->warning("Dropping remainder of lost PDU (lower edge middle segments, vr_ur=%d, vr_ur_in_rx_sdu=%d)\n", logger.warning("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 {
log->info_hex(rx_sdu->msg, logger.info(rx_sdu->msg,
rx_sdu->N_bytes, rx_sdu->N_bytes,
"%s Rx SDU vr_ur=%d, i=%d (lower edge middle segments)", "%s Rx SDU vr_ur=%d, i=%d (lower edge middle segments)",
rb_name.c_str(), rb_name.c_str(),
@ -422,7 +422,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) {
log->error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().\n"); logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().");
return; return;
} }
} }
@ -431,7 +431,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)) {
log->info("Writing last segment in SDU buffer. Lower edge vr_ur=%d, Buffer size=%d, segment size=%d\n", logger.info("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);
@ -441,11 +441,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)) {
log->warning("Dropping remainder of lost PDU (lower edge last segments)\n"); logger.warning("Dropping remainder of lost PDU (lower edge last segments)");
rx_sdu->clear(); rx_sdu->clear();
metrics.num_lost_pdus++; metrics.num_lost_pdus++;
} else { } else {
log->info_hex( logger.info(
rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU vr_ur=%d (lower edge last segments)", rb_name.c_str(), vr_ur); rx_sdu->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++;
@ -457,7 +457,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) {
log->error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().\n"); logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().");
return; return;
} }
} }
@ -474,11 +474,11 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
// Now update vr_ur until we reach an SN we haven't yet received // 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)) {
log->debug("Reassemble loop for vr_ur=%d\n", vr_ur); logger.debug("Reassemble loop for vr_ur=%d", vr_ur);
if (not pdu_belongs_to_rx_sdu()) { if (not pdu_belongs_to_rx_sdu()) {
log->warning( logger.warning(
"PDU SN=%d lost, stop reassambling SDU (vr_ur_in_rx_sdu=%d)\n", vr_ur_in_rx_sdu + 1, vr_ur_in_rx_sdu); "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();
} }
@ -486,7 +486,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];
log->debug("Handling SDU segment i=%d with len=%d of vr_ur=%d N_li=%d [%s]\n", logger.debug("Handling SDU segment i=%d with len=%d of vr_ur=%d N_li=%d [%s]",
i, i,
len, len,
vr_ur, vr_ur,
@ -494,11 +494,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)) {
log->warning_hex( logger.warning(
rx_window[vr_ur].buf->msg, len, "Dropping first %d B of SN=%d due to lost start segment\n", 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) {
log->error("Dropping remaining remainder of SN=%d too (N_bytes=%u < len=%d)\n", logger.error("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);
@ -518,7 +518,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()) {
log->error("Dropping PDU %d due to buffer mis-alignment (current segment len %d B, received %d B)\n", logger.error("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);
@ -528,14 +528,14 @@ 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()) {
log->info_hex(rx_window[vr_ur].buf->msg, len, "Copying first %d bytes of new SDU\n", len); logger.info(rx_window[vr_ur].buf->msg, len, "Copying first %d bytes of new SDU", len);
log->info("Updating vr_ur_in_rx_sdu. old=%d, new=%d\n", vr_ur_in_rx_sdu, vr_ur); logger.info("Updating vr_ur_in_rx_sdu. old=%d, new=%d", vr_ur_in_rx_sdu, vr_ur);
vr_ur_in_rx_sdu = vr_ur; vr_ur_in_rx_sdu = vr_ur;
} else { } else {
log->info_hex(rx_window[vr_ur].buf->msg, logger.info(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\n", "vr_ur_in_rx_sdu=%d, vr_ur=%d, rx_mod=%d, last_mod=%d",
len, len,
rx_sdu->N_bytes, rx_sdu->N_bytes,
rx_window[vr_ur].buf->N_bytes, rx_window[vr_ur].buf->N_bytes,
@ -552,7 +552,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()) {
log->info_hex(rx_sdu->msg, logger.info(rx_sdu->msg,
rx_sdu->N_bytes, rx_sdu->N_bytes,
"%s Rx SDU vr_ur=%d, i=%d, (update vr_ur middle segments)", "%s Rx SDU vr_ur=%d, i=%d, (update vr_ur middle segments)",
rb_name.c_str(), rb_name.c_str(),
@ -568,11 +568,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) {
log->error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().\n"); logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().");
return; return;
} }
} else { } else {
log->warning("Dropping remainder of lost PDU (update vr_ur middle segments, vr_ur=%d, vr_ur_in_rx_sdu=%d)\n", logger.warning("Dropping remainder of lost PDU (update vr_ur middle segments, vr_ur=%d, vr_ur_in_rx_sdu=%d)",
vr_ur, vr_ur,
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
@ -586,7 +586,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)) {
log->warning("Dropping PDU %d during last segment handling due to lost start segment\n", vr_ur); logger.warning("Dropping PDU %d during last segment handling due to lost start segment", vr_ur);
rx_sdu->clear(); rx_sdu->clear();
metrics.num_lost_pdus++; metrics.num_lost_pdus++;
goto clean_up_rx_window; goto clean_up_rx_window;
@ -595,10 +595,10 @@ void rlc_um_lte::rlc_um_lte_rx::reassemble_rx_sdus()
if (rx_sdu->N_bytes < SRSLTE_MAX_BUFFER_SIZE_BYTES && if (rx_sdu->N_bytes < SRSLTE_MAX_BUFFER_SIZE_BYTES &&
rx_window[vr_ur].buf->N_bytes < SRSLTE_MAX_BUFFER_SIZE_BYTES && rx_window[vr_ur].buf->N_bytes < SRSLTE_MAX_BUFFER_SIZE_BYTES &&
rx_window[vr_ur].buf->N_bytes + rx_sdu->N_bytes < SRSLTE_MAX_BUFFER_SIZE_BYTES) { rx_window[vr_ur].buf->N_bytes + rx_sdu->N_bytes < SRSLTE_MAX_BUFFER_SIZE_BYTES) {
log->info_hex(rx_window[vr_ur].buf->msg, logger.info(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\n", "segment size=%d",
vr_ur, vr_ur,
vr_ur_in_rx_sdu, vr_ur_in_rx_sdu,
rx_sdu->N_bytes, rx_sdu->N_bytes,
@ -606,7 +606,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 {
log->error("Out of bounds while reassembling SDU buffer in UM: sdu_len=%d, window_buffer_len=%d, vr_ur=%d\n", logger.error("Out of bounds while reassembling SDU buffer in UM: sdu_len=%d, window_buffer_len=%d, vr_ur=%d",
rx_sdu->N_bytes, rx_sdu->N_bytes,
rx_window[vr_ur].buf->N_bytes, rx_window[vr_ur].buf->N_bytes,
vr_ur); vr_ur);
@ -614,11 +614,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)) {
log->warning("Dropping remainder of lost PDU (update vr_ur last segments)\n"); logger.warning("Dropping remainder of lost PDU (update vr_ur last segments)");
rx_sdu->clear(); rx_sdu->clear();
metrics.num_lost_pdus++; metrics.num_lost_pdus++;
} else { } else {
log->info_hex( logger.info(
rx_sdu->msg, rx_sdu->N_bytes, "%s Rx SDU vr_ur=%d (update vr_ur last segments)", rb_name.c_str(), vr_ur); rx_sdu->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++;
@ -630,7 +630,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) {
log->error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().\n"); logger.error("Fatal Error: Couldn't allocate buffer in rlc_um::reassemble_rx_sdus().");
return; return;
} }
} }
@ -677,9 +677,9 @@ void rlc_um_lte::rlc_um_lte_rx::timer_expired(uint32_t timeout_id)
{ {
if (reordering_timer.id() == timeout_id) { if (reordering_timer.id() == timeout_id) {
// 36.322 v10 Section 5.1.2.2.4 // 36.322 v10 Section 5.1.2.2.4
log->info("%s reordering timeout expiry - updating vr_ur and reassembling\n", rb_name.c_str()); logger.info("%s reordering timeout expiry - updating vr_ur and reassembling", rb_name.c_str());
log->warning("Lost PDU SN=%d\n", vr_ur); logger.warning("Lost PDU SN=%d", vr_ur);
pdu_lost = true; pdu_lost = true;
if (rx_sdu != NULL) { if (rx_sdu != NULL) {
@ -688,9 +688,9 @@ void rlc_um_lte::rlc_um_lte_rx::timer_expired(uint32_t timeout_id)
while (RX_MOD_BASE(vr_ur) < RX_MOD_BASE(vr_ux)) { 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;
log->debug("Entering Reassemble from timeout id=%d\n", timeout_id); logger.debug("Entering Reassemble from timeout id=%d", timeout_id);
reassemble_rx_sdus(); reassemble_rx_sdus();
log->debug("Finished reassemble from timeout id=%d\n", timeout_id); logger.debug("Finished reassemble from timeout id=%d", timeout_id);
} }
if (RX_MOD_BASE(vr_uh) > RX_MOD_BASE(vr_ur)) { if (RX_MOD_BASE(vr_uh) > RX_MOD_BASE(vr_ur)) {
@ -708,7 +708,7 @@ void rlc_um_lte::rlc_um_lte_rx::timer_expired(uint32_t timeout_id)
void rlc_um_lte::rlc_um_lte_rx::debug_state() void rlc_um_lte::rlc_um_lte_rx::debug_state()
{ {
log->debug("%s vr_ur = %d, vr_ux = %d, vr_uh = %d\n", rb_name.c_str(), vr_ur, vr_ux, vr_uh); logger.debug("%s vr_ur = %d, vr_ux = %d, vr_uh = %d", rb_name.c_str(), vr_ur, vr_ux, vr_uh);
} }
/**************************************************************************** /****************************************************************************

82
lib/src/upper/rlc_um_nr.cc
Unescape Escape View File

@ -17,12 +17,12 @@
namespace srslte { namespace srslte {
rlc_um_nr::rlc_um_nr(srslte::log_ref log_, rlc_um_nr::rlc_um_nr(srslog::basic_logger& logger,
uint32_t lcid_, uint32_t lcid_,
srsue::pdcp_interface_rlc* pdcp_, srsue::pdcp_interface_rlc* pdcp_,
srsue::rrc_interface_rlc* rrc_, srsue::rrc_interface_rlc* rrc_,
srslte::timer_handler* timers_) : srslte::timer_handler* timers_) :
rlc_um_base(log_, lcid_, pdcp_, rrc_, timers_) rlc_um_base(logger, lcid_, pdcp_, rrc_, timers_)
{} {}
rlc_um_nr::~rlc_um_nr() rlc_um_nr::~rlc_um_nr()
@ -48,7 +48,7 @@ bool rlc_um_nr::configure(const rlc_config_t& cnfg_)
return false; return false;
} }
log->info("%s configured in %s: sn_field_length=%u bits\n", logger.info("%s configured in %s: sn_field_length=%u bits",
rb_name.c_str(), rb_name.c_str(),
srslte::to_string(cnfg_.rlc_mode).c_str(), srslte::to_string(cnfg_.rlc_mode).c_str(),
srslte::to_number(cfg.um_nr.sn_field_length)); srslte::to_number(cfg.um_nr.sn_field_length));
@ -94,7 +94,7 @@ bool rlc_um_nr::rlc_um_nr_tx::configure(const rlc_config_t& cnfg_, std::string r
cfg = cnfg_; cfg = cnfg_;
if (cfg.um_nr.mod == 0) { if (cfg.um_nr.mod == 0) {
log->error("Error configuring %s RLC UM: tx_mod==0\n", rb_name.c_str()); logger.error("Error configuring %s RLC UM: tx_mod==0", rb_name.c_str());
return false; return false;
} }
@ -120,7 +120,7 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p
int pdu_space = SRSLTE_MIN(nof_bytes, pdu->get_tailroom()); int pdu_space = SRSLTE_MIN(nof_bytes, pdu->get_tailroom());
if (pdu_space <= head_len + 1) { if (pdu_space <= head_len + 1) {
log->warning("%s Cannot build a PDU - %d bytes available, %d bytes required for header\n", logger.warning("%s Cannot build a PDU - %d bytes available, %d bytes required for header",
rb_name.c_str(), rb_name.c_str(),
nof_bytes, nof_bytes,
head_len); head_len);
@ -131,17 +131,16 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p
if (tx_sdu) { 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;
log->debug( logger.debug(
"%s adding remainder of SDU segment - %d bytes of %d remaining\n", rb_name.c_str(), 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);
pdu_ptr += to_move; pdu_ptr += to_move;
pdu->N_bytes += to_move; pdu->N_bytes += to_move;
tx_sdu->N_bytes -= to_move; tx_sdu->N_bytes -= to_move;
tx_sdu->msg += to_move; tx_sdu->msg += to_move;
if (tx_sdu->N_bytes == 0) { if (tx_sdu->N_bytes == 0) {
log->debug("%s Complete SDU scheduled for tx. Stack latency: %ld us\n", logger.debug(
rb_name.c_str(), "%s Complete SDU scheduled for tx. Stack latency: %ld us", rb_name.c_str(), tx_sdu->get_latency_us().count());
tx_sdu->get_latency_us().count());
tx_sdu.reset(); tx_sdu.reset();
header.si = rlc_nr_si_field_t::last_segment; header.si = rlc_nr_si_field_t::last_segment;
} else { } else {
@ -151,22 +150,21 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p
header.so = next_so; header.so = next_so;
} else { } else {
// Pull SDU from queue // Pull SDU from queue
log->debug("pdu_space=%d, head_len=%d\n", pdu_space, head_len); logger.debug("pdu_space=%d, head_len=%d", pdu_space, head_len);
head_len = rlc_um_nr_packed_length(header); head_len = rlc_um_nr_packed_length(header);
tx_sdu = tx_sdu_queue.read(); tx_sdu = tx_sdu_queue.read();
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;
log->debug("%s adding new SDU - %d bytes of %d remaining\n", rb_name.c_str(), to_move, tx_sdu->N_bytes); logger.debug("%s adding new SDU - %d bytes of %d remaining", rb_name.c_str(), to_move, tx_sdu->N_bytes);
memcpy(pdu_ptr, tx_sdu->msg, to_move); memcpy(pdu_ptr, tx_sdu->msg, to_move);
pdu_ptr += to_move; pdu_ptr += to_move;
pdu->N_bytes += to_move; pdu->N_bytes += to_move;
tx_sdu->N_bytes -= to_move; tx_sdu->N_bytes -= to_move;
tx_sdu->msg += to_move; tx_sdu->msg += to_move;
if (tx_sdu->N_bytes == 0) { if (tx_sdu->N_bytes == 0) {
log->debug("%s Complete SDU scheduled for tx. Stack latency: %ld us\n", logger.debug(
rb_name.c_str(), "%s Complete SDU scheduled for tx. Stack latency: %ld us", rb_name.c_str(), tx_sdu->get_latency_us().count());
tx_sdu->get_latency_us().count());
tx_sdu.reset(); tx_sdu.reset();
header.si = rlc_nr_si_field_t::full_sdu; header.si = rlc_nr_si_field_t::full_sdu;
} else { } else {
@ -189,7 +187,7 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p
memcpy(payload, pdu->msg, pdu->N_bytes); memcpy(payload, pdu->msg, pdu->N_bytes);
uint32_t ret = pdu->N_bytes; uint32_t ret = pdu->N_bytes;
log->info_hex(payload, ret, "%s Tx PDU SN=%d (%d B)\n", rb_name.c_str(), header.sn, pdu->N_bytes); logger.info(payload, ret, "%s Tx PDU SN=%d (%d B)", rb_name.c_str(), header.sn, pdu->N_bytes);
debug_state(); debug_state();
@ -198,7 +196,7 @@ int rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8_t* p
void rlc_um_nr::rlc_um_nr_tx::debug_state() void rlc_um_nr::rlc_um_nr_tx::debug_state()
{ {
log->debug("%s TX_Next=%d, next_so=%d\n", rb_name.c_str(), TX_Next, next_so); logger.debug("%s TX_Next=%d, next_so=%d", rb_name.c_str(), TX_Next, next_so);
} }
void rlc_um_nr::rlc_um_nr_tx::reset() void rlc_um_nr::rlc_um_nr_tx::reset()
@ -218,13 +216,13 @@ rlc_um_nr::rlc_um_nr_rx::rlc_um_nr_rx(rlc_um_base* parent_) :
bool rlc_um_nr::rlc_um_nr_rx::configure(const rlc_config_t& cnfg_, std::string rb_name_) bool rlc_um_nr::rlc_um_nr_rx::configure(const rlc_config_t& cnfg_, std::string rb_name_)
{ {
if (cfg.um_nr.mod == 0) { if (cfg.um_nr.mod == 0) {
log->error("Error configuring %s RLC UM: rx_mod==0\n", rb_name.c_str()); logger.error("Error configuring %s RLC UM: rx_mod==0", rb_name.c_str());
return false; return false;
} }
// check timer // check timer
if (not reassembly_timer.is_valid()) { if (not reassembly_timer.is_valid()) {
log->error("Configuring RLC UM NR RX: timers not configured\n"); logger.error("Configuring RLC UM NR RX: timers not configured");
return false; return false;
} }
@ -273,9 +271,9 @@ void rlc_um_nr::rlc_um_nr_rx::timer_expired(uint32_t timeout_id)
{ {
std::lock_guard<std::mutex> lock(mutex); std::lock_guard<std::mutex> lock(mutex);
if (reassembly_timer.id() == timeout_id) { if (reassembly_timer.id() == timeout_id) {
log->info("%s reassembly timeout expiry - updating RX_Next_Reassembly and reassembling\n", rb_name.c_str()); logger.info("%s reassembly timeout expiry - updating RX_Next_Reassembly and reassembling", rb_name.c_str());
log->warning("Lost PDU SN: %d\n", RX_Next_Reassembly); logger.warning("Lost PDU SN: %d", RX_Next_Reassembly);
metrics.num_lost_pdus++; metrics.num_lost_pdus++;
if (rx_sdu != nullptr) { if (rx_sdu != nullptr) {
@ -330,7 +328,7 @@ unique_byte_buffer_t rlc_um_nr::rlc_um_nr_rx::rlc_um_nr_strip_pdu_header(const r
{ {
unique_byte_buffer_t sdu = make_byte_buffer(); unique_byte_buffer_t sdu = make_byte_buffer();
if (!sdu) { if (!sdu) {
log->error("Discarting packet: no space in buffer pool\n"); logger.error("Discarting packet: no space in buffer pool");
return nullptr; return nullptr;
} }
memcpy(sdu->msg, payload, nof_bytes); memcpy(sdu->msg, payload, nof_bytes);
@ -357,7 +355,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn)
// iterate over received segments and try to assemble full SDU // iterate over received segments and try to assemble full SDU
auto& pdu = rx_window.at(sn); auto& pdu = rx_window.at(sn);
for (auto it = pdu.segments.begin(); it != pdu.segments.end();) { for (auto it = pdu.segments.begin(); it != pdu.segments.end();) {
log->debug("Have %s segment with SO=%d for SN=%d\n", logger.debug("Have %s segment with SO=%d for SN=%d",
to_string_short(it->second.header.si).c_str(), to_string_short(it->second.header.si).c_str(),
it->second.header.so, it->second.header.so,
it->second.header.sn); it->second.header.sn);
@ -367,19 +365,19 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn)
// reuse buffer of first segment for final SDU // reuse buffer of first segment for final SDU
pdu.sdu = std::move(it->second.buf); pdu.sdu = std::move(it->second.buf);
pdu.next_expected_so = pdu.sdu->N_bytes; pdu.next_expected_so = pdu.sdu->N_bytes;
log->debug("Reusing first segment of SN=%d for final SDU\n", it->second.header.sn); logger.debug("Reusing first segment of SN=%d for final SDU", it->second.header.sn);
it = pdu.segments.erase(it); it = pdu.segments.erase(it);
} else { } else {
log->debug("SDU buffer already allocated. Possible retransmission of first segment.\n"); logger.debug("SDU buffer already allocated. Possible retransmission of first segment.");
if (it->second.header.so != pdu.next_expected_so) { if (it->second.header.so != pdu.next_expected_so) {
log->error("Invalid PDU. SO doesn't match. Discarting all segments of SN=%d.\n", sn); logger.error("Invalid PDU. SO doesn't match. Discarting all segments of SN=%d.", sn);
rx_window.erase(sn); rx_window.erase(sn);
return; return;
} }
} }
} else { } else {
if (it->second.buf->N_bytes > pdu.sdu->get_tailroom()) { if (it->second.buf->N_bytes > pdu.sdu->get_tailroom()) {
log->error("Cannot fit RLC PDU in SDU buffer (tailroom=%d, len=%d), dropping both. Erasing SN=%d.\n", logger.error("Cannot fit RLC PDU in SDU buffer (tailroom=%d, len=%d), dropping both. Erasing SN=%d.",
rx_sdu->get_tailroom(), rx_sdu->get_tailroom(),
it->second.buf->N_bytes, it->second.buf->N_bytes,
it->second.header.sn); it->second.header.sn);
@ -392,12 +390,12 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn)
memcpy(pdu.sdu->msg + pdu.sdu->N_bytes, it->second.buf->msg, it->second.buf->N_bytes); memcpy(pdu.sdu->msg + pdu.sdu->N_bytes, it->second.buf->msg, it->second.buf->N_bytes);
pdu.sdu->N_bytes += it->second.buf->N_bytes; pdu.sdu->N_bytes += it->second.buf->N_bytes;
pdu.next_expected_so += it->second.buf->N_bytes; pdu.next_expected_so += it->second.buf->N_bytes;
log->debug("Appended SO=%d of SN=%d\n", it->second.header.so, it->second.header.sn); logger.debug("Appended SO=%d of SN=%d", it->second.header.so, it->second.header.sn);
it = pdu.segments.erase(it); it = pdu.segments.erase(it);
if (pdu.next_expected_so == pdu.total_sdu_length) { if (pdu.next_expected_so == pdu.total_sdu_length) {
// deliver full SDU to upper layers // deliver full SDU to upper layers
log->info("Delivering %s SDU SN=%d (%d B)", rb_name.c_str(), sn, pdu.sdu->N_bytes); logger.info("Delivering %s SDU SN=%d (%d B)", rb_name.c_str(), sn, pdu.sdu->N_bytes);
pdcp->write_pdu(lcid, std::move(pdu.sdu)); pdcp->write_pdu(lcid, std::move(pdu.sdu));
// find next SN in rx buffer // find next SN in rx buffer
@ -406,7 +404,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn)
while (RX_MOD_NR_BASE(RX_Next_Reassembly) < RX_MOD_NR_BASE(RX_Next_Highest)) { while (RX_MOD_NR_BASE(RX_Next_Reassembly) < RX_MOD_NR_BASE(RX_Next_Highest)) {
RX_Next_Reassembly = (RX_Next_Reassembly + 1) % cfg.um_nr.mod; RX_Next_Reassembly = (RX_Next_Reassembly + 1) % cfg.um_nr.mod;
} }
log->debug("Updating RX_Next_Reassembly=%d\n", RX_Next_Reassembly); logger.debug("Updating RX_Next_Reassembly=%d", RX_Next_Reassembly);
} }
// delete PDU from rx_window // delete PDU from rx_window
@ -424,12 +422,12 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn)
if (not sn_in_reassembly_window(sn)) { if (not sn_in_reassembly_window(sn)) {
// update RX_Next_highest // update RX_Next_highest
RX_Next_Highest = sn + 1; RX_Next_Highest = sn + 1;
log->debug("Updating RX_Next_Highest=%d\n", RX_Next_Highest); logger.debug("Updating RX_Next_Highest=%d", RX_Next_Highest);
// drop all SNs outside of new rx window // drop all SNs outside of new rx window
for (auto it = rx_window.begin(); it != rx_window.end();) { for (auto it = rx_window.begin(); it != rx_window.end();) {
if (not sn_in_reassembly_window(it->first)) { if (not sn_in_reassembly_window(it->first)) {
log->info("%s SN: %d outside rx window [%d:%d] - discarding\n", logger.info("%s SN: %d outside rx window [%d:%d] - discarding",
rb_name.c_str(), rb_name.c_str(),
it->first, it->first,
RX_Next_Highest - cfg.um_nr.UM_Window_Size, RX_Next_Highest - cfg.um_nr.UM_Window_Size,
@ -446,7 +444,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn)
for (const auto& rx_pdu : rx_window) { for (const auto& rx_pdu : rx_window) {
if (rx_pdu.first >= RX_MOD_NR_BASE(RX_Next_Highest - cfg.um_nr.UM_Window_Size)) { if (rx_pdu.first >= RX_MOD_NR_BASE(RX_Next_Highest - cfg.um_nr.UM_Window_Size)) {
RX_Next_Reassembly = rx_pdu.first; RX_Next_Reassembly = rx_pdu.first;
log->debug("Updating RX_Next_Reassembly=%d\n", RX_Next_Reassembly); logger.debug("Updating RX_Next_Reassembly=%d", RX_Next_Reassembly);
break; break;
} }
} }
@ -468,7 +466,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn)
} }
} }
} else { } else {
log->error("SN=%d does not exist in Rx buffer\n", sn); logger.error("SN=%d does not exist in Rx buffer", sn);
} }
} }
@ -477,7 +475,7 @@ inline void rlc_um_nr::rlc_um_nr_rx::update_total_sdu_length(rlc_umd_pdu_segment
{ {
if (rx_pdu.header.si == rlc_nr_si_field_t::last_segment) { if (rx_pdu.header.si == rlc_nr_si_field_t::last_segment) {
pdu_segments.total_sdu_length = rx_pdu.header.so + rx_pdu.buf->N_bytes; pdu_segments.total_sdu_length = rx_pdu.header.so + rx_pdu.buf->N_bytes;
log->info("%s updating total SDU length for SN=%d to %d B\n", logger.info("%s updating total SDU length for SN=%d to %d B",
rb_name.c_str(), rb_name.c_str(),
rx_pdu.header.sn, rx_pdu.header.sn,
pdu_segments.total_sdu_length); pdu_segments.total_sdu_length);
@ -491,7 +489,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_byt
rlc_um_nr_pdu_header_t header = {}; rlc_um_nr_pdu_header_t header = {};
rlc_um_nr_read_data_pdu_header(payload, nof_bytes, cfg.um_nr.sn_field_length, &header); rlc_um_nr_read_data_pdu_header(payload, nof_bytes, cfg.um_nr.sn_field_length, &header);
log->debug_hex(payload, nof_bytes, "RX %s Rx data PDU (%d B)", rb_name.c_str(), nof_bytes); logger.debug(payload, nof_bytes, "RX %s Rx data PDU (%d B)", rb_name.c_str(), nof_bytes);
// check if PDU contains a SN // check if PDU contains a SN
if (header.si == rlc_nr_si_field_t::full_sdu) { if (header.si == rlc_nr_si_field_t::full_sdu) {
@ -499,10 +497,10 @@ void rlc_um_nr::rlc_um_nr_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_byt
unique_byte_buffer_t sdu = rlc_um_nr_strip_pdu_header(header, payload, nof_bytes); unique_byte_buffer_t sdu = rlc_um_nr_strip_pdu_header(header, payload, nof_bytes);
// deliver to PDCP // deliver to PDCP
log->info("Delivering %s SDU (%d B)", rb_name.c_str(), sdu->N_bytes); logger.info("Delivering %s SDU (%d B)", rb_name.c_str(), sdu->N_bytes);
pdcp->write_pdu(lcid, std::move(sdu)); pdcp->write_pdu(lcid, std::move(sdu));
} else if (sn_invalid_for_rx_buffer(header.sn)) { } else if (sn_invalid_for_rx_buffer(header.sn)) {
log->info("%s Discarding SN=%d\n", rb_name.c_str(), header.sn); logger.info("%s Discarding SN=%d", rb_name.c_str(), header.sn);
// Nothing else to do here .. // Nothing else to do here ..
} else { } else {
// place PDU in receive buffer // place PDU in receive buffer
@ -513,7 +511,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_byt
// check if this SN is already present in rx buffer // check if this SN is already present in rx buffer
if (rx_window.find(header.sn) == rx_window.end()) { if (rx_window.find(header.sn) == rx_window.end()) {
// first received segment of this SN, add to rx buffer // first received segment of this SN, add to rx buffer
log->info("%s placing %s segment of SN=%d in Rx buffer\n", logger.info("%s placing %s segment of SN=%d in Rx buffer",
rb_name.c_str(), rb_name.c_str(),
to_string_short(header.si).c_str(), to_string_short(header.si).c_str(),
header.sn); header.sn);
@ -523,7 +521,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_byt
rx_window[header.sn] = std::move(pdu_segments); rx_window[header.sn] = std::move(pdu_segments);
} else { } else {
// other segment for this SN already present, update received data // other segment for this SN already present, update received data
log->info("%s updating SN=%d at SO=%d with %d B\n", logger.info("%s updating SN=%d at SO=%d with %d B",
rb_name.c_str(), rb_name.c_str(),
rx_pdu.header.sn, rx_pdu.header.sn,
rx_pdu.header.so, rx_pdu.header.so,
@ -547,7 +545,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_data_pdu(uint8_t* payload, uint32_t nof_byt
void rlc_um_nr::rlc_um_nr_rx::debug_state() void rlc_um_nr::rlc_um_nr_rx::debug_state()
{ {
log->debug("%s RX_Next_Reassembly=%d, RX_Timer_Trigger=%d, RX_Next_Highest=%d, t_Reassembly=%s\n", logger.debug("%s RX_Next_Reassembly=%d, RX_Timer_Trigger=%d, RX_Next_Highest=%d, t_Reassembly=%s",
rb_name.c_str(), rb_name.c_str(),
RX_Next_Reassembly, RX_Next_Reassembly,
RX_Timer_Trigger, RX_Timer_Trigger,
@ -593,7 +591,7 @@ uint32_t rlc_um_nr_read_data_pdu_header(const uint8_t* payload,
if (header->si == rlc_nr_si_field_t::first_segment) { if (header->si == rlc_nr_si_field_t::first_segment) {
// make sure two reserved bits are not set // make sure two reserved bits are not set
if (((*ptr >> 4) & 0x03) != 0) { if (((*ptr >> 4) & 0x03) != 0) {
fprintf(stderr, "Malformed PDU, reserved bits are set.\n"); fprintf(stderr, "Malformed PDU, reserved bits are set.");
return 0; return 0;
} }
} }

2
lib/test/upper/rlc_am_control_test.cc
Unescape Escape View File

@ -64,6 +64,8 @@ int status_pdu_with_nacks_test1()
int main(int argc, char** argv) int main(int argc, char** argv)
{ {
srslog::init();
TESTASSERT(simple_status_pdu_test1() == SRSLTE_SUCCESS); TESTASSERT(simple_status_pdu_test1() == SRSLTE_SUCCESS);
TESTASSERT(status_pdu_with_nacks_test1() == SRSLTE_SUCCESS); TESTASSERT(status_pdu_with_nacks_test1() == SRSLTE_SUCCESS);

3
lib/test/upper/rlc_am_data_test.cc
Unescape Escape View File

@ -143,9 +143,12 @@ int test4()
int main(int argc, char** argv) int main(int argc, char** argv)
{ {
srslog::init();
TESTASSERT(test1() == SRSLTE_SUCCESS); TESTASSERT(test1() == SRSLTE_SUCCESS);
TESTASSERT(test2() == SRSLTE_SUCCESS); TESTASSERT(test2() == SRSLTE_SUCCESS);
TESTASSERT(test3() == SRSLTE_SUCCESS); TESTASSERT(test3() == SRSLTE_SUCCESS);
TESTASSERT(test4() == SRSLTE_SUCCESS); TESTASSERT(test4() == SRSLTE_SUCCESS);
return SRSLTE_SUCCESS; return SRSLTE_SUCCESS;
} }

2
lib/test/upper/rlc_am_nr_pdu_test.cc
Unescape Escape View File

@ -292,6 +292,8 @@ int main(int argc, char** argv)
pcap_handle->open("rlc_am_nr_pdu_test.pcap"); pcap_handle->open("rlc_am_nr_pdu_test.pcap");
#endif #endif
srslog::init();
if (rlc_am_nr_pdu_test1()) { if (rlc_am_nr_pdu_test1()) {
fprintf(stderr, "rlc_am_nr_pdu_test1() failed.\n"); fprintf(stderr, "rlc_am_nr_pdu_test1() failed.\n");
return SRSLTE_ERROR; return SRSLTE_ERROR;

87
lib/test/upper/rlc_am_test.cc
Unescape Escape View File

@ -23,9 +23,6 @@
using namespace srsue; using namespace srsue;
using namespace srslte; using namespace srslte;
srslte::log_ref rrc_log1("RLC_AM_1");
srslte::log_ref rrc_log2("RLC_AM_2");
bool rx_is_tx(const rlc_bearer_metrics_t& rlc1_metrics, const rlc_bearer_metrics_t& rlc2_metrics) bool rx_is_tx(const rlc_bearer_metrics_t& rlc1_metrics, const rlc_bearer_metrics_t& rlc2_metrics)
{ {
if (rlc1_metrics.num_tx_pdu_bytes != rlc2_metrics.num_rx_pdu_bytes) { if (rlc1_metrics.num_tx_pdu_bytes != rlc2_metrics.num_rx_pdu_bytes) {
@ -154,8 +151,8 @@ int basic_test()
timer_handler timers(8); timer_handler timers(8);
byte_buffer_t pdu_bufs[NBUFS]; byte_buffer_t pdu_bufs[NBUFS];
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
// before configuring entity // before configuring entity
TESTASSERT(0 == rlc1.get_buffer_state()); TESTASSERT(0 == rlc1.get_buffer_state());
@ -211,8 +208,8 @@ int concat_test()
rlc_am_tester tester; rlc_am_tester tester;
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -287,8 +284,8 @@ int segment_test(bool in_seq_rx)
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
int len = 0; int len = 0;
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -382,8 +379,8 @@ int retx_test()
timer_handler timers(8); timer_handler timers(8);
int len = 0; int len = 0;
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -518,8 +515,8 @@ int segment_retx_test()
timer_handler timers(8); timer_handler timers(8);
int len = 0; int len = 0;
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -642,8 +639,8 @@ int resegment_test_1()
timer_handler timers(8); timer_handler timers(8);
int len = 0; int len = 0;
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -707,7 +704,7 @@ int resegment_test_1()
TESTASSERT(12 == rlc1.get_buffer_state()); // 2 byte header + 10 data TESTASSERT(12 == rlc1.get_buffer_state()); // 2 byte header + 10 data
// Check notifications // Check notifications
rrc_log1->debug("%ld\n", tester.notified_counts.size()); srslog::fetch_basic_logger("RLC_AM_1").debug("%ld", tester.notified_counts.size());
TESTASSERT(tester.notified_counts.size() == 4); TESTASSERT(tester.notified_counts.size() == 4);
for (int i = 0; i < 5; i++) { for (int i = 0; i < 5; i++) {
auto it = tester.notified_counts.find(i); auto it = tester.notified_counts.find(i);
@ -801,8 +798,8 @@ int resegment_test_2()
timer_handler timers(8); timer_handler timers(8);
int len = 0; int len = 0;
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -934,8 +931,8 @@ int resegment_test_3()
rlc_am_tester tester; rlc_am_tester tester;
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -1065,8 +1062,8 @@ int resegment_test_4()
rlc_am_tester tester; rlc_am_tester tester;
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -1198,8 +1195,8 @@ int resegment_test_5()
rlc_am_tester tester; rlc_am_tester tester;
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -1326,8 +1323,8 @@ int resegment_test_6()
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
int len = 0; int len = 0;
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -1497,8 +1494,8 @@ int resegment_test_7()
#endif #endif
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -1685,8 +1682,8 @@ int resegment_test_8()
#endif #endif
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -1827,7 +1824,7 @@ bool reset_test()
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
int len = 0; int len = 0;
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -1869,7 +1866,7 @@ bool resume_test()
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
int len = 0; int len = 0;
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -1910,7 +1907,7 @@ bool stop_test()
rlc_am_tester tester; rlc_am_tester tester;
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -1937,8 +1934,8 @@ bool status_pdu_test()
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
int len = 0; int len = 0;
rlc_am_lte rlc1(rrc_log1, 1, &tester, &tester, &timers); rlc_am_lte rlc1(srslog::fetch_basic_logger("RLC_AM_1"), 1, &tester, &tester, &timers);
rlc_am_lte rlc2(rrc_log2, 1, &tester, &tester, &timers); rlc_am_lte rlc2(srslog::fetch_basic_logger("RLC_AM_2"), 1, &tester, &tester, &timers);
if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) { if (not rlc1.configure(rlc_config_t::default_rlc_am_config())) {
return -1; return -1;
@ -2049,10 +2046,14 @@ bool status_pdu_test()
int main(int argc, char** argv) int main(int argc, char** argv)
{ {
rrc_log1->set_level(srslte::LOG_LEVEL_DEBUG); srslog::init();
rrc_log2->set_level(srslte::LOG_LEVEL_DEBUG);
rrc_log1->set_hex_limit(-1); auto& logger_rrc1 = srslog::fetch_basic_logger("RLC_AM_1", false);
rrc_log2->set_hex_limit(-1); logger_rrc1.set_level(srslog::basic_levels::debug);
logger_rrc1.set_hex_dump_max_size(-1);
auto& logger_rrc2 = srslog::fetch_basic_logger("RLC_AM_2", false);
logger_rrc2.set_level(srslog::basic_levels::debug);
logger_rrc2.set_hex_dump_max_size(-1);
if (basic_test()) { if (basic_test()) {
printf("basic_test failed\n"); printf("basic_test failed\n");
@ -2114,8 +2115,8 @@ int main(int argc, char** argv)
exit(-1); exit(-1);
}; };
rrc_log1->set_hex_limit(100); logger_rrc1.set_hex_dump_max_size(100);
rrc_log2->set_hex_limit(100); logger_rrc2.set_hex_dump_max_size(100);
if (resegment_test_7()) { if (resegment_test_7()) {
printf("resegment_test_7 failed\n"); printf("resegment_test_7 failed\n");
exit(-1); exit(-1);
@ -2125,8 +2126,8 @@ int main(int argc, char** argv)
printf("resegment_test_8 failed\n"); printf("resegment_test_8 failed\n");
exit(-1); exit(-1);
}; };
rrc_log1->set_hex_limit(-1); logger_rrc1.set_hex_dump_max_size(-1);
rrc_log2->set_hex_limit(-1); logger_rrc2.set_hex_dump_max_size(-1);
if (reset_test()) { if (reset_test()) {
printf("reset_test failed\n"); printf("reset_test failed\n");

19
lib/test/upper/rlc_common_test.cc
Unescape Escape View File

@ -64,19 +64,20 @@ public:
int meas_obj_test() int meas_obj_test()
{ {
srslte::log_ref log1("RLC_1"); auto& logger_rlc1 = srslog::fetch_basic_logger("RLC_1", false);
srslte::log_ref log2("RLC_2"); logger_rlc1.set_level(srslog::basic_levels::debug);
log1->set_level(srslte::LOG_LEVEL_DEBUG); logger_rlc1.set_hex_dump_max_size(-1);
log2->set_level(srslte::LOG_LEVEL_DEBUG); auto& logger_rlc2 = srslog::fetch_basic_logger("RLC_2", false);
log1->set_hex_limit(-1); logger_rlc2.set_level(srslog::basic_levels::debug);
log2->set_hex_limit(-1); logger_rlc2.set_hex_dump_max_size(-1);
rlc_tester tester; rlc_tester tester;
srslte::timer_handler timers(1); srslte::timer_handler timers(1);
int len = 0; int len = 0;
rlc rlc1(log1->get_service_name().c_str()); rlc rlc1(logger_rlc1.id().c_str());
rlc rlc2(log2->get_service_name().c_str()); rlc rlc2(logger_rlc2.id().c_str());
rlc1.init(&tester, &tester, &timers, 0); rlc1.init(&tester, &tester, &timers, 0);
rlc2.init(&tester, &tester, &timers, 0); rlc2.init(&tester, &tester, &timers, 0);
@ -195,6 +196,8 @@ int meas_obj_test()
int main(int argc, char** argv) int main(int argc, char** argv)
{ {
srslog::init();
if (meas_obj_test()) { if (meas_obj_test()) {
return -1; return -1;
} }

50
lib/test/upper/rlc_stress_test.cc
Unescape Escape View File

@ -153,14 +153,14 @@ public:
pcap(pcap_), pcap(pcap_),
lcid(lcid_), lcid(lcid_),
timers(timers_), timers(timers_),
log("MAC "), logger(srslog::fetch_basic_logger("MAC", false)),
thread("MAC_DUMMY"), thread("MAC_DUMMY"),
real_dist(0.0, 1.0), real_dist(0.0, 1.0),
mt19937(1234), mt19937(1234),
pool(byte_buffer_pool::get_instance()) pool(byte_buffer_pool::get_instance())
{ {
log.set_level(static_cast<LOG_LEVEL_ENUM>(args.log_level)); logger.set_level(static_cast<srslog::basic_levels>(args.log_level));
log.set_hex_limit(LOG_HEX_LIMIT); logger.set_hex_dump_max_size(LOG_HEX_LIMIT);
} }
void stop() void stop()
@ -227,7 +227,7 @@ private:
// Cut // Cut
if ((real_dist(mt19937) < args.pdu_cut_rate)) { if ((real_dist(mt19937) < args.pdu_cut_rate)) {
int cut_pdu_len = static_cast<int>(pdu_len * real_dist(mt19937)); int cut_pdu_len = static_cast<int>(pdu_len * real_dist(mt19937));
log.info("Cutting MAC PDU len (%d B -> %d B)\n", pdu_len, cut_pdu_len); logger.info("Cutting MAC PDU len (%d B -> %d B)", pdu_len, cut_pdu_len);
pdu_len = cut_pdu_len; pdu_len = cut_pdu_len;
} }
@ -242,7 +242,7 @@ private:
pcap->write_ul_ccch(pdu->msg, pdu_len); pcap->write_ul_ccch(pdu->msg, pdu_len);
} }
} else { } else {
log.warning_hex(pdu->msg, pdu->N_bytes, "Dropping RLC PDU (%d B)\n", pdu->N_bytes); logger.warning(pdu->msg, pdu->N_bytes, "Dropping RLC PDU (%d B)", pdu->N_bytes);
skip_action = true; // Avoid drop duplicating this PDU skip_action = true; // Avoid drop duplicating this PDU
} }
@ -251,7 +251,7 @@ private:
it++; it++;
skip_action = false; // Allow action on the next PDU skip_action = false; // Allow action on the next PDU
} else { } else {
log.warning_hex(pdu->msg, pdu->N_bytes, "Duplicating RLC PDU (%d B)\n", pdu->N_bytes); logger.warning(pdu->msg, pdu->N_bytes, "Duplicating RLC PDU (%d B)", pdu->N_bytes);
skip_action = true; // Avoid drop of this PDU skip_action = true; // Avoid drop of this PDU
} }
} }
@ -300,7 +300,7 @@ private:
stress_test_args_t args; stress_test_args_t args;
rlc_pcap* pcap; rlc_pcap* pcap;
uint32_t lcid; uint32_t lcid;
srslte::log_filter log; srslog::basic_logger& logger;
srslte::timer_handler* timers = nullptr; srslte::timer_handler* timers = nullptr;
srslte::block_queue<srslte::move_task_t> pending_tasks; srslte::block_queue<srslte::move_task_t> pending_tasks;
@ -314,10 +314,18 @@ class rlc_tester : public pdcp_interface_rlc, public rrc_interface_rlc, public t
{ {
public: public:
rlc_tester(rlc_interface_pdcp* rlc_, std::string name_, stress_test_args_t args_, uint32_t lcid_) : rlc_tester(rlc_interface_pdcp* rlc_, std::string name_, stress_test_args_t args_, uint32_t lcid_) :
log("TEST"), rlc(rlc_), run_enable(true), rx_pdus(), name(name_), args(args_), lcid(lcid_), thread("RLC_TESTER") log("TEST"),
logger(srslog::fetch_basic_logger("TEST", false)),
rlc(rlc_),
run_enable(true),
rx_pdus(),
name(name_),
args(args_),
lcid(lcid_),
thread("RLC_TESTER")
{ {
log.set_level(srslte::LOG_LEVEL_ERROR); logger.set_level(srslog::basic_levels::error);
log.set_hex_limit(LOG_HEX_LIMIT); logger.set_hex_dump_max_size(LOG_HEX_LIMIT);
} }
void stop() void stop()
@ -331,7 +339,7 @@ public:
{ {
assert(rx_lcid == lcid); assert(rx_lcid == lcid);
if (sdu->N_bytes != args.sdu_size) { if (sdu->N_bytes != args.sdu_size) {
log.error_hex(sdu->msg, sdu->N_bytes, "Received SDU with size %d, expected %d.\n", sdu->N_bytes, args.sdu_size); logger.error(sdu->msg, sdu->N_bytes, "Received SDU with size %d, expected %d.", sdu->N_bytes, args.sdu_size);
if (args.pedantic_sdu_check) { if (args.pedantic_sdu_check) {
exit(-1); exit(-1);
} }
@ -381,6 +389,7 @@ private:
uint64_t rx_pdus; uint64_t rx_pdus;
uint32_t lcid; uint32_t lcid;
srslte::log_filter log; srslte::log_filter log;
srslog::basic_logger& logger;
std::string name; std::string name;
@ -391,12 +400,13 @@ private:
void stress_test(stress_test_args_t args) void stress_test(stress_test_args_t args)
{ {
srslte::log_ref log1("RLC_1"); auto& log1 = srslog::fetch_basic_logger("RLC_1", false);
srslte::log_ref log2("RLC_2"); log1.set_level(static_cast<srslog::basic_levels>(args.log_level));
log1->set_level(static_cast<LOG_LEVEL_ENUM>(args.log_level)); log1.set_hex_dump_max_size(LOG_HEX_LIMIT);
log2->set_level(static_cast<LOG_LEVEL_ENUM>(args.log_level)); auto& log2 = srslog::fetch_basic_logger("RLC_2", false);
log1->set_hex_limit(LOG_HEX_LIMIT); log2.set_level(static_cast<srslog::basic_levels>(args.log_level));
log2->set_hex_limit(LOG_HEX_LIMIT); log2.set_hex_dump_max_size(LOG_HEX_LIMIT);
rlc_pcap pcap; rlc_pcap pcap;
uint32_t lcid = 1; uint32_t lcid = 1;
@ -455,8 +465,8 @@ void stress_test(stress_test_args_t args)
srslte::timer_handler timers(8); srslte::timer_handler timers(8);
rlc rlc1(log1->get_service_name().c_str()); rlc rlc1(log1.id().c_str());
rlc rlc2(log2->get_service_name().c_str()); rlc rlc2(log2.id().c_str());
rlc_tester tester1(&rlc1, "tester1", args, lcid); rlc_tester tester1(&rlc1, "tester1", args, lcid);
rlc_tester tester2(&rlc2, "tester2", args, lcid); rlc_tester tester2(&rlc2, "tester2", args, lcid);
@ -539,6 +549,8 @@ int main(int argc, char** argv)
stress_test_args_t args = {}; stress_test_args_t args = {};
parse_args(&args, argc, argv); parse_args(&args, argc, argv);
srslog::init();
if (args.zero_seed) { if (args.zero_seed) {
srand(0); srand(0);
} else { } else {

2
lib/test/upper/rlc_um_data_test.cc
Unescape Escape View File

@ -24,6 +24,8 @@ uint32_t PDU2_LEN = 4;
int main(int argc, char** argv) int main(int argc, char** argv)
{ {
srslog::init();
srslte::rlc_umd_pdu_header_t h; srslte::rlc_umd_pdu_header_t h;
srslte::byte_buffer_t b1, b2; srslte::byte_buffer_t b1, b2;

2
lib/test/upper/rlc_um_nr_pdu_test.cc
Unescape Escape View File

@ -202,6 +202,8 @@ int main(int argc, char** argv)
pcap_handle->open("rlc_um_nr_pdu_test.pcap"); pcap_handle->open("rlc_um_nr_pdu_test.pcap");
#endif #endif
srslog::init();
if (rlc_um_nr_pdu_test1()) { if (rlc_um_nr_pdu_test1()) {
fprintf(stderr, "rlc_um_nr_pdu_test1() failed.\n"); fprintf(stderr, "rlc_um_nr_pdu_test1() failed.\n");
return SRSLTE_ERROR; return SRSLTE_ERROR;

21
lib/test/upper/rlc_um_nr_test.cc
Unescape Escape View File

@ -72,17 +72,17 @@ class rlc_um_nr_test_context1
{ {
public: public:
rlc_um_nr_test_context1() : rlc_um_nr_test_context1() :
log1("RLC_UM_1"), logger1(srslog::fetch_basic_logger("RLC_UM_1", false)),
log2("RLC_UM_2"), logger2(srslog::fetch_basic_logger("RLC_UM_2", false)),
timers(16), timers(16),
rlc1(log1, 3, &tester, &tester, &timers), rlc1(logger1, 3, &tester, &tester, &timers),
rlc2(log2, 3, &tester, &tester, &timers) rlc2(logger2, 3, &tester, &tester, &timers)
{ {
// setup logging // setup logging
log1->set_level(srslte::LOG_LEVEL_DEBUG); logger1.set_level(srslog::basic_levels::debug);
log2->set_level(srslte::LOG_LEVEL_DEBUG); logger1.set_hex_dump_max_size(-1);
log1->set_hex_limit(-1); logger2.set_level(srslog::basic_levels::debug);
log2->set_hex_limit(-1); logger2.set_hex_dump_max_size(-1);
// configure RLC entities // configure RLC entities
rlc_config_t cnfg = rlc_config_t::default_rlc_um_nr_config(6); rlc_config_t cnfg = rlc_config_t::default_rlc_um_nr_config(6);
@ -96,7 +96,8 @@ public:
tester.set_expected_sdu_len(1); tester.set_expected_sdu_len(1);
} }
srslte::log_ref log1, log2; srslog::basic_logger& logger1;
srslog::basic_logger& logger2;
srslte::timer_handler timers; srslte::timer_handler timers;
rlc_um_tester tester; rlc_um_tester tester;
rlc_um_nr rlc1, rlc2; rlc_um_nr rlc1, rlc2;
@ -561,6 +562,8 @@ int main(int argc, char** argv)
pcap_handle->open("rlc_um_nr_test.pcap"); pcap_handle->open("rlc_um_nr_test.pcap");
#endif #endif
srslog::init();
if (rlc_um_nr_test1()) { if (rlc_um_nr_test1()) {
fprintf(stderr, "rlc_um_nr_test1() failed.\n"); fprintf(stderr, "rlc_um_nr_test1() failed.\n");
return SRSLTE_ERROR; return SRSLTE_ERROR;

21
lib/test/upper/rlc_um_test.cc
Unescape Escape View File

@ -34,17 +34,17 @@ class rlc_um_lte_test_context1
{ {
public: public:
rlc_um_lte_test_context1() : rlc_um_lte_test_context1() :
log1("RLC_UM_1"), logger1(srslog::fetch_basic_logger("RLC_UM_1", false)),
log2("RLC_UM_2"), logger2(srslog::fetch_basic_logger("RLC_UM_2", false)),
timers(16), timers(16),
rlc1(log1, 3, &tester, &tester, &timers), rlc1(logger1, 3, &tester, &tester, &timers),
rlc2(log2, 3, &tester, &tester, &timers) rlc2(logger2, 3, &tester, &tester, &timers)
{ {
// setup logging // setup logging
log1->set_level(srslte::LOG_LEVEL_DEBUG); logger1.set_level(srslog::basic_levels::debug);
log2->set_level(srslte::LOG_LEVEL_DEBUG); logger1.set_hex_dump_max_size(-1);
log1->set_hex_limit(-1); logger2.set_level(srslog::basic_levels::debug);
log2->set_hex_limit(-1); logger2.set_hex_dump_max_size(-1);
// configure RLC entities // configure RLC entities
rlc_config_t cnfg = rlc_config_t::default_rlc_um_config(10); rlc_config_t cnfg = rlc_config_t::default_rlc_um_config(10);
@ -58,7 +58,8 @@ public:
tester.set_expected_sdu_len(1); tester.set_expected_sdu_len(1);
} }
srslte::log_ref log1, log2; srslog::basic_logger& logger1;
srslog::basic_logger& logger2;
srslte::timer_handler timers; srslte::timer_handler timers;
rlc_um_tester tester; rlc_um_tester tester;
rlc_um_lte rlc1, rlc2; rlc_um_lte rlc1, rlc2;
@ -426,6 +427,8 @@ int pdu_pack_no_space_test()
int main(int argc, char** argv) int main(int argc, char** argv)
{ {
srslog::init();
if (meas_obj_test()) { if (meas_obj_test()) {
return -1; return -1;
} }

Write Preview
Loading…
Cancel
Save