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

lib,rlc: changed RLC UM NR to use new logging macros

Browse Source
master
Pedro Alvarez 3 years ago
parent b53da22eb1
commit 87607a4ea7
1 changed files with 61 additions and 74 deletions
Show Stats Download Patch File Download Diff File

87
lib/src/rlc/rlc_um_nr.cc
Unescape Escape View File

@ -49,8 +49,7 @@ bool rlc_um_nr::configure(const rlc_config_t& cnfg_)
return false; return false;
} }
logger.info("%s configured in %s: sn_field_length=%u bits, t_reassembly=%d ms", RlcInfo("configured in %s: sn_field_length=%u bits, t_reassembly=%d ms",
rb_name.c_str(),
srsran::to_string(cnfg_.rlc_mode), srsran::to_string(cnfg_.rlc_mode),
srsran::to_number(cfg.um_nr.sn_field_length), srsran::to_number(cfg.um_nr.sn_field_length),
cfg.um_nr.t_reassembly_ms); cfg.um_nr.t_reassembly_ms);
@ -133,7 +132,7 @@ uint32_t rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8
{ {
// Sanity check (we need at least 2B for a SDU) // Sanity check (we need at least 2B for a SDU)
if (nof_bytes < 2) { if (nof_bytes < 2) {
logger.warning("%s Cannot build a PDU with %d byte.", rb_name.c_str(), nof_bytes); RlcWarning("Cannot build a PDU with %d byte.", nof_bytes);
return 0; return 0;
} }
@ -170,10 +169,7 @@ uint32_t rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8
// Calculate actual header length // Calculate actual header length
uint32_t head_len = rlc_um_nr_packed_length(header); uint32_t head_len = rlc_um_nr_packed_length(header);
if (pdu_space <= head_len + 1) { if (pdu_space <= head_len + 1) {
logger.info("%s Cannot build a PDU - %d bytes available, %d bytes required for header", RlcInfo("Cannot build a PDU - %d bytes available, %d bytes required for header", nof_bytes, head_len);
rb_name.c_str(),
nof_bytes,
head_len);
return 0; return 0;
} }
@ -182,7 +178,7 @@ uint32_t rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8
uint32_t to_move = space >= tx_sdu->N_bytes ? tx_sdu->N_bytes : space; uint32_t to_move = space >= tx_sdu->N_bytes ? tx_sdu->N_bytes : space;
// Log // Log
logger.debug("%s adding %s - (%d/%d)", rb_name.c_str(), to_string(header.si).c_str(), to_move, tx_sdu->N_bytes); RlcDebug("adding %s - (%d/%d)", to_string(header.si).c_str(), to_move, tx_sdu->N_bytes);
// Move data from SDU to PDU // Move data from SDU to PDU
uint8_t* pdu_ptr = pdu->msg; uint8_t* pdu_ptr = pdu->msg;
@ -217,9 +213,9 @@ uint32_t rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8
if (header.si == rlc_nr_si_field_t::full_sdu) { if (header.si == rlc_nr_si_field_t::full_sdu) {
// log without SN // log without SN
logger.info(payload, ret, "%s Tx PDU (%d B)", rb_name.c_str(), pdu->N_bytes); RlcHexInfo(payload, ret, "Tx PDU (%d B)", pdu->N_bytes);
} else { } else {
logger.info(payload, ret, "%s Tx PDU SN=%d (%d B)", rb_name.c_str(), header.sn, pdu->N_bytes); RlcHexInfo(payload, ret, "Tx PDU SN=%d (%d B)", header.sn, pdu->N_bytes);
} }
debug_state(); debug_state();
@ -229,7 +225,7 @@ uint32_t rlc_um_nr::rlc_um_nr_tx::build_data_pdu(unique_byte_buffer_t pdu, uint8
void rlc_um_nr::rlc_um_nr_tx::debug_state() void rlc_um_nr::rlc_um_nr_tx::debug_state()
{ {
logger.debug("%s TX_Next=%d, next_so=%d", rb_name.c_str(), TX_Next, next_so); RlcDebug("TX_Next=%d, next_so=%d", TX_Next, next_so);
} }
void rlc_um_nr::rlc_um_nr_tx::reset() void rlc_um_nr::rlc_um_nr_tx::reset()
@ -251,9 +247,11 @@ bool rlc_um_nr::rlc_um_nr_rx::configure(const rlc_config_t& cnfg_, std::string r
mod = (cfg.um_nr.sn_field_length == rlc_um_nr_sn_size_t::size6bits) ? 64 : 4096; mod = (cfg.um_nr.sn_field_length == rlc_um_nr_sn_size_t::size6bits) ? 64 : 4096;
UM_Window_Size = (cfg.um_nr.sn_field_length == rlc_um_nr_sn_size_t::size6bits) ? 32 : 2048; UM_Window_Size = (cfg.um_nr.sn_field_length == rlc_um_nr_sn_size_t::size6bits) ? 32 : 2048;
rb_name = rb_name_;
// check timer // check timer
if (not reassembly_timer.is_valid()) { if (not reassembly_timer.is_valid()) {
logger.error("Configuring RLC UM NR RX: timers not configured"); RlcError("Configuring RLC UM NR RX: timers not configured");
return false; return false;
} }
@ -263,8 +261,6 @@ bool rlc_um_nr::rlc_um_nr_rx::configure(const rlc_config_t& cnfg_, std::string r
[this](uint32_t tid) { timer_expired(tid); }); [this](uint32_t tid) { timer_expired(tid); });
} }
rb_name = rb_name_;
return true; return true;
} }
@ -304,9 +300,7 @@ 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) {
logger.debug("%s reassembly timeout expiry for SN=%d - updating RX_Next_Reassembly and reassembling", RlcDebug("reassembly timeout expiry for SN=%d - updating RX_Next_Reassembly and reassembling", RX_Next_Reassembly);
rb_name.c_str(),
RX_Next_Reassembly);
metrics.num_lost_pdus++; metrics.num_lost_pdus++;
@ -334,7 +328,7 @@ void rlc_um_nr::rlc_um_nr_rx::timer_expired(uint32_t timeout_id)
if (RX_MOD_NR_BASE(RX_Next_Highest) > RX_MOD_NR_BASE(RX_Next_Reassembly + 1) || if (RX_MOD_NR_BASE(RX_Next_Highest) > RX_MOD_NR_BASE(RX_Next_Reassembly + 1) ||
((RX_MOD_NR_BASE(RX_Next_Highest) == RX_MOD_NR_BASE(RX_Next_Reassembly + 1) && ((RX_MOD_NR_BASE(RX_Next_Highest) == RX_MOD_NR_BASE(RX_Next_Reassembly + 1) &&
has_missing_byte_segment(RX_Next_Reassembly)))) { has_missing_byte_segment(RX_Next_Reassembly)))) {
logger.debug("%s starting reassembly timer for SN=%d", rb_name.c_str(), RX_Next_Reassembly); RlcDebug("starting reassembly timer for SN=%d", rb_name.c_str(), RX_Next_Reassembly);
reassembly_timer.run(); reassembly_timer.run();
RX_Timer_Trigger = RX_Next_Highest; RX_Timer_Trigger = RX_Next_Highest;
} }
@ -363,7 +357,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 == nullptr) { if (sdu == nullptr) {
logger.error("Couldn't allocate PDU in %s().", __FUNCTION__); RlcError("Couldn't allocate PDU in %s().", __FUNCTION__);
return nullptr; return nullptr;
} }
memcpy(sdu->msg, payload, nof_bytes); memcpy(sdu->msg, payload, nof_bytes);
@ -392,7 +386,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();) {
logger.debug("Have %s segment with SO=%d for SN=%d", RlcDebug("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);
@ -402,19 +396,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;
logger.debug("Reusing first segment of SN=%d for final SDU", it->second.header.sn); RlcDebug("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 {
logger.debug("SDU buffer already allocated. Possible retransmission of first segment."); RlcDebug("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) {
logger.error("Invalid PDU. SO doesn't match. Discarting all segments of SN=%d.", sn); RlcError("Invalid PDU. SO doesn't match. Discarding 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()) {
logger.error("Cannot fit RLC PDU in SDU buffer (tailroom=%d, len=%d), dropping both. Erasing SN=%d.", RlcError("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);
@ -427,7 +421,7 @@ 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;
logger.debug("Appended SO=%d of SN=%d", it->second.header.so, it->second.header.sn); RlcDebug("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) {
@ -444,7 +438,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn)
if (sdu_complete) { if (sdu_complete) {
// deliver full SDU to upper layers // deliver full SDU to upper layers
logger.info("%s Rx SDU (%d B)", rb_name.c_str(), pdu.sdu->N_bytes); RlcInfo("Rx SDU (%d B)", pdu.sdu->N_bytes);
pdcp->write_pdu(lcid, std::move(pdu.sdu)); pdcp->write_pdu(lcid, std::move(pdu.sdu));
// delete PDU from rx_window // delete PDU from rx_window
@ -457,26 +451,25 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn)
RX_Next_Reassembly = RX_Next_Highest; RX_Next_Reassembly = RX_Next_Highest;
} else { } else {
for (auto it = rx_window.begin(); it != rx_window.end(); ++it) { for (auto it = rx_window.begin(); it != rx_window.end(); ++it) {
logger.debug("SN=%d has %zd segments", it->first, it->second.segments.size()); RlcDebug("SN=%d has %zd segments", it->first, it->second.segments.size());
if (RX_MOD_NR_BASE(it->first) > RX_MOD_NR_BASE(RX_Next_Reassembly)) { if (RX_MOD_NR_BASE(it->first) > RX_MOD_NR_BASE(RX_Next_Reassembly)) {
RX_Next_Reassembly = it->first; RX_Next_Reassembly = it->first;
break; break;
} }
} }
} }
logger.debug("Updating RX_Next_Reassembly=%d", RX_Next_Reassembly); RlcDebug("Updating RX_Next_Reassembly=%d", RX_Next_Reassembly);
} }
} else if (not sn_in_reassembly_window(sn)) { } else if (not sn_in_reassembly_window(sn)) {
// SN outside of rx window // SN outside of rx window
RX_Next_Highest = (sn + 1) % mod; // update RX_Next_highest RX_Next_Highest = (sn + 1) % mod; // update RX_Next_highest
logger.debug("Updating RX_Next_Highest=%d", RX_Next_Highest); RlcDebug("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)) {
logger.info("%s SN: %d outside rx window [%d:%d] - discarding", RlcInfo("SN=%d outside rx window [%d:%d] - discarding",
rb_name.c_str(),
it->first, it->first,
RX_Next_Highest - UM_Window_Size, RX_Next_Highest - UM_Window_Size,
RX_Next_Highest); RX_Next_Highest);
@ -492,7 +485,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 - UM_Window_Size)) { if (rx_pdu.first >= RX_MOD_NR_BASE(RX_Next_Highest - UM_Window_Size)) {
RX_Next_Reassembly = rx_pdu.first; RX_Next_Reassembly = rx_pdu.first;
logger.debug("%s Updating RX_Next_Reassembly=%d", rb_name.c_str(), RX_Next_Reassembly); RlcDebug("Updating RX_Next_Reassembly=%d", RX_Next_Reassembly);
break; break;
} }
} }
@ -503,7 +496,7 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn)
if (RX_Timer_Trigger <= RX_Next_Reassembly || if (RX_Timer_Trigger <= RX_Next_Reassembly ||
(not sn_in_reassembly_window(RX_Timer_Trigger) and RX_Timer_Trigger != RX_Next_Highest) || (not sn_in_reassembly_window(RX_Timer_Trigger) and RX_Timer_Trigger != RX_Next_Highest) ||
((RX_Next_Highest == RX_Next_Reassembly + 1) && not has_missing_byte_segment(RX_Next_Reassembly))) { ((RX_Next_Highest == RX_Next_Reassembly + 1) && not has_missing_byte_segment(RX_Next_Reassembly))) {
logger.debug("%s stopping reassembly timer", rb_name.c_str()); RlcDebug("stopping reassembly timer");
reassembly_timer.stop(); reassembly_timer.stop();
} }
} }
@ -512,13 +505,13 @@ void rlc_um_nr::rlc_um_nr_rx::handle_rx_buffer_update(const uint32_t sn)
if ((RX_MOD_NR_BASE(RX_Next_Highest) > RX_MOD_NR_BASE(RX_Next_Reassembly + 1)) || if ((RX_MOD_NR_BASE(RX_Next_Highest) > RX_MOD_NR_BASE(RX_Next_Reassembly + 1)) ||
((RX_MOD_NR_BASE(RX_Next_Highest) == RX_MOD_NR_BASE(RX_Next_Reassembly + 1)) && ((RX_MOD_NR_BASE(RX_Next_Highest) == RX_MOD_NR_BASE(RX_Next_Reassembly + 1)) &&
has_missing_byte_segment(RX_Next_Reassembly))) { has_missing_byte_segment(RX_Next_Reassembly))) {
logger.debug("%s Starting reassembly timer for SN=%d", rb_name.c_str(), sn); RlcDebug("Starting reassembly timer for SN=%d", sn);
reassembly_timer.run(); reassembly_timer.run();
RX_Timer_Trigger = RX_Next_Highest; RX_Timer_Trigger = RX_Next_Highest;
} }
} }
} else { } else {
logger.error("%s SN=%d does not exist in Rx buffer", rb_name.c_str(), sn); RlcError("SN=%d does not exist in Rx buffer", sn);
} }
} }
@ -527,10 +520,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;
logger.debug("%s updating total SDU length for SN=%d to %d B", RlcDebug("updating total SDU length for SN=%d to %d B", rx_pdu.header.sn, pdu_segments.total_sdu_length);
rb_name.c_str(),
rx_pdu.header.sn,
pdu_segments.total_sdu_length);
} }
}; };
@ -541,7 +531,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);
logger.debug(payload, nof_bytes, "%s Rx data PDU (%d B)", rb_name.c_str(), nof_bytes); RlcHexDebug(payload, nof_bytes, "Rx data PDU (%d B)", 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) {
@ -549,10 +539,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
logger.info("%s Rx SDU (%d B)", rb_name.c_str(), sdu->N_bytes); RlcInfo("Rx SDU (%d B)", 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)) {
logger.info("%s Discarding SN=%d", rb_name.c_str(), header.sn); RlcInfo("Discarding SN=%d", header.sn);
// Nothing else to do here .. // Nothing else to do here ..
} else { } else {
// place PDU in receive buffer // place PDU in receive buffer
@ -563,10 +553,9 @@ 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
logger.debug(rx_pdu.buf->msg, RlcHexDebug(rx_pdu.buf->msg,
rx_pdu.buf->N_bytes, rx_pdu.buf->N_bytes,
"%s placing %s segment of SN=%d (%d B) in Rx buffer", "placing %s segment of SN=%d (%d B) in Rx buffer",
rb_name.c_str(),
to_string_short(header.si).c_str(), to_string_short(header.si).c_str(),
header.sn, header.sn,
rx_pdu.buf->N_bytes); rx_pdu.buf->N_bytes);
@ -576,10 +565,9 @@ 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
logger.debug(rx_pdu.buf->msg, RlcHexDebug(rx_pdu.buf->msg,
rx_pdu.buf->N_bytes, rx_pdu.buf->N_bytes,
"%s updating SN=%d at SO=%d with %d B", "updating SN=%d at SO=%d with %d B",
rb_name.c_str(),
rx_pdu.header.sn, rx_pdu.header.sn,
rx_pdu.header.so, rx_pdu.header.so,
rx_pdu.buf->N_bytes); rx_pdu.buf->N_bytes);
@ -602,8 +590,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()
{ {
logger.debug("%s RX_Next_Reassembly=%d, RX_Timer_Trigger=%d, RX_Next_Highest=%d, t_Reassembly=%s", RlcDebug("RX_Next_Reassembly=%d, RX_Timer_Trigger=%d, RX_Next_Highest=%d, t_Reassembly=%s",
rb_name.c_str(),
RX_Next_Reassembly, RX_Next_Reassembly,
RX_Timer_Trigger, RX_Timer_Trigger,
RX_Next_Highest, RX_Next_Highest,

Write Preview
Loading…
Cancel
Save