Addressing reviewers comments to #2290.

Removing unecessary \n for logs and changed log of PDCP info queue
 capacity to debug to avoid log spam.
Changed log level for unhandled S1AP messages from error to warning
 in EPC to avoid failing tests because of error message.
Changed usage of allocate_unique_buffer to make_unique_buffer()
master
Pedro Alvarez 4 years ago
parent fcaaf72187
commit 492ea2a5a8

@ -76,8 +76,6 @@ private:
srsue::rrc_interface_pdcp* rrc = nullptr; srsue::rrc_interface_pdcp* rrc = nullptr;
srsue::gw_interface_pdcp* gw = nullptr; srsue::gw_interface_pdcp* gw = nullptr;
byte_buffer_pool* pool = nullptr;
// State variables, as defined in TS 36 323, section 7.1 // State variables, as defined in TS 36 323, section 7.1
pdcp_lte_state_t st = {}; pdcp_lte_state_t st = {};
@ -89,7 +87,6 @@ private:
std::map<uint32_t, timer_handler::unique_timer> discard_timers_map; std::map<uint32_t, timer_handler::unique_timer> discard_timers_map;
// TX Queue // TX Queue
uint32_t tx_queue_capacity = 512;
std::map<uint32_t, unique_byte_buffer_t> undelivered_sdus_queue; std::map<uint32_t, unique_byte_buffer_t> undelivered_sdus_queue;
void handle_srb_pdu(srslte::unique_byte_buffer_t pdu); void handle_srb_pdu(srslte::unique_byte_buffer_t pdu);

@ -189,7 +189,6 @@ private:
srslte::timer_handler::unique_timer status_prohibit_timer; srslte::timer_handler::unique_timer status_prohibit_timer;
// SDU info for PDCP notifications // SDU info for PDCP notifications
uint32_t pdcp_info_queue_capacity = 512;
std::map<uint32_t, pdcp_sdu_info_t> undelivered_sdu_info_queue = {}; std::map<uint32_t, pdcp_sdu_info_t> undelivered_sdu_info_queue = {};
// Callback function for buffer status report // Callback function for buffer status report

@ -128,7 +128,7 @@ void pdcp_entity_lte::write_sdu(unique_byte_buffer_t sdu)
discard_timer.set(static_cast<uint32_t>(cfg.discard_timer), discard_fnc); discard_timer.set(static_cast<uint32_t>(cfg.discard_timer), discard_fnc);
discard_timer.run(); discard_timer.run();
discard_timers_map.insert(std::make_pair(tx_count, std::move(discard_timer))); discard_timers_map.insert(std::make_pair(tx_count, std::move(discard_timer)));
log->debug("Discard Timer set for SN %u. Timeout: %ums\n", tx_count, static_cast<uint32_t>(cfg.discard_timer)); logger.debug("Discard Timer set for SN %u. Timeout: %ums", tx_count, static_cast<uint32_t>(cfg.discard_timer));
} }
// Append MAC (SRBs only) // Append MAC (SRBs only)
@ -364,21 +364,17 @@ void pdcp_entity_lte::handle_am_drb_pdu(srslte::unique_byte_buffer_t pdu)
***************************************************************************/ ***************************************************************************/
bool pdcp_entity_lte::store_sdu(uint32_t tx_count, const unique_byte_buffer_t& sdu) bool pdcp_entity_lte::store_sdu(uint32_t tx_count, const unique_byte_buffer_t& sdu)
{ {
// Check capacity logger.debug(
if (undelivered_sdus_queue.size() >= tx_queue_capacity) { "Storing SDU in undelivered SDUs queue. TX_COUNT=%d, Queue size=%ld", tx_count, undelivered_sdus_queue.size());
log->warning("The undelivered PDU queue is growing large. TX_COUNT=%d, Queue size=%ld\n",
tx_count,
undelivered_sdus_queue.size());
}
// Check wether PDU is already in the queue // Check wether PDU is already in the queue
if (undelivered_sdus_queue.find(tx_count) != undelivered_sdus_queue.end()) { if (undelivered_sdus_queue.find(tx_count) != undelivered_sdus_queue.end()) {
log->error("PDU already exists in the queue. TX_COUNT=%d\n", tx_count); logger.error("PDU already exists in the queue. TX_COUNT=%d", tx_count);
return false; return false;
} }
// Copy PDU contents into queue // Copy PDU contents into queue
unique_byte_buffer_t sdu_copy = allocate_unique_buffer(*pool); unique_byte_buffer_t sdu_copy = make_byte_buffer();
memcpy(sdu_copy->msg, sdu->msg, sdu->N_bytes); memcpy(sdu_copy->msg, sdu->msg, sdu->N_bytes);
sdu_copy->N_bytes = sdu->N_bytes; sdu_copy->N_bytes = sdu->N_bytes;
@ -392,14 +388,14 @@ bool pdcp_entity_lte::store_sdu(uint32_t tx_count, const unique_byte_buffer_t& s
// Discard Timer Callback (discardTimer) // Discard Timer Callback (discardTimer)
void pdcp_entity_lte::discard_callback::operator()(uint32_t timer_id) void pdcp_entity_lte::discard_callback::operator()(uint32_t timer_id)
{ {
parent->log->debug("Discard timer expired for PDU with SN = %d\n", discard_sn); parent->logger.debug("Discard timer expired for PDU with SN = %d", discard_sn);
// Discard PDU if unacknowledged // Discard PDU if unacknowledged
if (parent->undelivered_sdus_queue.find(discard_sn) != parent->undelivered_sdus_queue.end()) { if (parent->undelivered_sdus_queue.find(discard_sn) != parent->undelivered_sdus_queue.end()) {
parent->undelivered_sdus_queue.erase(discard_sn); parent->undelivered_sdus_queue.erase(discard_sn);
parent->log->debug("Removed undelivered PDU with TX_COUNT=%d\n", discard_sn); parent->logger.debug("Removed undelivered PDU with TX_COUNT=%d", discard_sn);
} else { } else {
parent->log->debug("Could not find PDU to discard. TX_COUNT=%d\n", discard_sn); parent->logger.debug("Could not find PDU to discard. TX_COUNT=%d", discard_sn);
} }
// Notify the RLC of the discard. It's the RLC to actually discard, if no segment was transmitted yet. // Notify the RLC of the discard. It's the RLC to actually discard, if no segment was transmitted yet.
@ -415,13 +411,13 @@ void pdcp_entity_lte::discard_callback::operator()(uint32_t timer_id)
***************************************************************************/ ***************************************************************************/
void pdcp_entity_lte::notify_delivery(const std::vector<uint32_t>& pdcp_sns) void pdcp_entity_lte::notify_delivery(const std::vector<uint32_t>& pdcp_sns)
{ {
log->debug("Received delivery notification from RLC. Number of PDU notified=%ld", pdcp_sns.size()); logger.debug("Received delivery notification from RLC. Number of PDU notified=%ld", pdcp_sns.size());
for (uint32_t sn : pdcp_sns) { for (uint32_t sn : pdcp_sns) {
// Find undelivered PDU info // Find undelivered PDU info
std::map<uint32_t, unique_byte_buffer_t>::iterator it = undelivered_sdus_queue.find(sn); std::map<uint32_t, unique_byte_buffer_t>::iterator it = undelivered_sdus_queue.find(sn);
if (it == undelivered_sdus_queue.end()) { if (it == undelivered_sdus_queue.end()) {
log->warning("Could not find PDU for delivery notification. Notified SN=%d\n", sn); logger.warning("Could not find PDU for delivery notification. Notified SN=%d", sn);
return; return;
} }
@ -475,7 +471,7 @@ std::map<uint32_t, srslte::unique_byte_buffer_t> pdcp_entity_lte::get_buffered_p
// TODO: investigate wheter the deep copy can be avoided by moving the undelivered SDU queue. // TODO: investigate wheter the deep copy can be avoided by moving the undelivered SDU queue.
// That can only be done just before the PDCP is disabled though. // That can only be done just before the PDCP is disabled though.
for (auto it = undelivered_sdus_queue.begin(); it != undelivered_sdus_queue.end(); it++) { for (auto it = undelivered_sdus_queue.begin(); it != undelivered_sdus_queue.end(); it++) {
cpy[it->first] = allocate_unique_buffer(*pool); cpy[it->first] = make_byte_buffer();
(*cpy[it->first]) = *(it->second); (*cpy[it->first]) = *(it->second);
} }
return cpy; return cpy;

@ -383,6 +383,9 @@ int rlc_am_lte::rlc_am_lte_tx::write_sdu(unique_byte_buffer_t sdu)
} }
// Store SDU info // Store SDU info
logger.debug(
"Storing PDCP SDU info in queue. PDCP_SN=%d, Queue Size=%ld", info.sn, undelivered_sdu_info_queue.size());
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) {
logger.error("PDCP SDU info already exists. SN=%d", info.sn); logger.error("PDCP SDU info already exists. SN=%d", info.sn);
@ -390,12 +393,6 @@ int rlc_am_lte::rlc_am_lte_tx::write_sdu(unique_byte_buffer_t sdu)
return SRSLTE_ERROR; return SRSLTE_ERROR;
} }
if (undelivered_sdu_info_queue.size() >= pdcp_info_queue_capacity) {
logger.warning("Undelivered PDCP SDU info queue is growing large. Queue size: %ld",
undelivered_sdu_info_queue.size());
}
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;

@ -17,8 +17,7 @@
*/ */
int test_tx_sdu_notify(const srslte::pdcp_lte_state_t& init_state, int test_tx_sdu_notify(const srslte::pdcp_lte_state_t& init_state,
srslte::pdcp_discard_timer_t discard_timeout, srslte::pdcp_discard_timer_t discard_timeout,
srslte::byte_buffer_pool* pool, srslog::basic_logger& logger)
srslte::log_ref log)
{ {
srslte::pdcp_config_t cfg = {1, srslte::pdcp_config_t cfg = {1,
srslte::PDCP_RB_IS_DRB, srslte::PDCP_RB_IS_DRB,
@ -28,7 +27,7 @@ int test_tx_sdu_notify(const srslte::pdcp_lte_state_t& init_state,
srslte::pdcp_t_reordering_t::ms500, srslte::pdcp_t_reordering_t::ms500,
discard_timeout}; discard_timeout};
pdcp_lte_test_helper pdcp_hlp(cfg, sec_cfg, log); pdcp_lte_test_helper pdcp_hlp(cfg, sec_cfg, logger);
srslte::pdcp_entity_lte* pdcp = &pdcp_hlp.pdcp; srslte::pdcp_entity_lte* pdcp = &pdcp_hlp.pdcp;
rlc_dummy* rlc = &pdcp_hlp.rlc; rlc_dummy* rlc = &pdcp_hlp.rlc;
srsue::stack_test_dummy* stack = &pdcp_hlp.stack; srsue::stack_test_dummy* stack = &pdcp_hlp.stack;
@ -36,11 +35,11 @@ int test_tx_sdu_notify(const srslte::pdcp_lte_state_t& init_state,
pdcp_hlp.set_pdcp_initial_state(init_state); pdcp_hlp.set_pdcp_initial_state(init_state);
// Write test SDU // Write test SDU
srslte::unique_byte_buffer_t sdu = allocate_unique_buffer(*pool); srslte::unique_byte_buffer_t sdu = srslte::make_byte_buffer();
sdu->append_bytes(sdu1, sizeof(sdu1)); sdu->append_bytes(sdu1, sizeof(sdu1));
pdcp->write_sdu(std::move(sdu)); pdcp->write_sdu(std::move(sdu));
srslte::unique_byte_buffer_t out_pdu = srslte::allocate_unique_buffer(*pool); srslte::unique_byte_buffer_t out_pdu = srslte::make_byte_buffer();
rlc->get_last_sdu(out_pdu); rlc->get_last_sdu(out_pdu);
TESTASSERT(out_pdu->N_bytes == 4); TESTASSERT(out_pdu->N_bytes == 4);
@ -63,8 +62,7 @@ int test_tx_sdu_notify(const srslte::pdcp_lte_state_t& init_state,
*/ */
int test_tx_sdu_discard(const srslte::pdcp_lte_state_t& init_state, int test_tx_sdu_discard(const srslte::pdcp_lte_state_t& init_state,
srslte::pdcp_discard_timer_t discard_timeout, srslte::pdcp_discard_timer_t discard_timeout,
srslte::byte_buffer_pool* pool, srslog::basic_logger& logger)
srslte::log_ref log)
{ {
srslte::pdcp_config_t cfg = {1, srslte::pdcp_config_t cfg = {1,
srslte::PDCP_RB_IS_DRB, srslte::PDCP_RB_IS_DRB,
@ -74,7 +72,7 @@ int test_tx_sdu_discard(const srslte::pdcp_lte_state_t& init_state,
srslte::pdcp_t_reordering_t::ms500, srslte::pdcp_t_reordering_t::ms500,
discard_timeout}; discard_timeout};
pdcp_lte_test_helper pdcp_hlp(cfg, sec_cfg, log); pdcp_lte_test_helper pdcp_hlp(cfg, sec_cfg, logger);
srslte::pdcp_entity_lte* pdcp = &pdcp_hlp.pdcp; srslte::pdcp_entity_lte* pdcp = &pdcp_hlp.pdcp;
rlc_dummy* rlc = &pdcp_hlp.rlc; rlc_dummy* rlc = &pdcp_hlp.rlc;
srsue::stack_test_dummy* stack = &pdcp_hlp.stack; srsue::stack_test_dummy* stack = &pdcp_hlp.stack;
@ -82,11 +80,11 @@ int test_tx_sdu_discard(const srslte::pdcp_lte_state_t& init_state,
pdcp_hlp.set_pdcp_initial_state(init_state); pdcp_hlp.set_pdcp_initial_state(init_state);
// Write test SDU // Write test SDU
srslte::unique_byte_buffer_t sdu = allocate_unique_buffer(*pool); srslte::unique_byte_buffer_t sdu = srslte::make_byte_buffer();
sdu->append_bytes(sdu1, sizeof(sdu1)); sdu->append_bytes(sdu1, sizeof(sdu1));
pdcp->write_sdu(std::move(sdu)); pdcp->write_sdu(std::move(sdu));
srslte::unique_byte_buffer_t out_pdu = srslte::allocate_unique_buffer(*pool); srslte::unique_byte_buffer_t out_pdu = srslte::make_byte_buffer();
rlc->get_last_sdu(out_pdu); rlc->get_last_sdu(out_pdu);
TESTASSERT(out_pdu->N_bytes == 4); TESTASSERT(out_pdu->N_bytes == 4);
@ -111,41 +109,40 @@ int test_tx_sdu_discard(const srslte::pdcp_lte_state_t& init_state,
* TX Test: PDCP Entity with SN LEN = 12 and 18. * TX Test: PDCP Entity with SN LEN = 12 and 18.
* PDCP entity configured with EIA2 and EEA2 * PDCP entity configured with EIA2 and EEA2
*/ */
int test_tx_discard_all(srslte::byte_buffer_pool* pool, srslte::log_ref log) int test_tx_discard_all(srslog::basic_logger& logger)
{ {
/* /*
* TX Test 1: PDCP Entity with SN LEN = 12 * TX Test 1: PDCP Entity with SN LEN = 12
* Test TX PDU discard. * Test TX PDU discard.
*/ */
TESTASSERT(test_tx_sdu_notify(normal_init_state, srslte::pdcp_discard_timer_t::ms50, pool, log) == 0); TESTASSERT(test_tx_sdu_notify(normal_init_state, srslte::pdcp_discard_timer_t::ms50, logger) == 0);
/* /*
* TX Test 2: PDCP Entity with SN LEN = 12 * TX Test 2: PDCP Entity with SN LEN = 12
* Test TX PDU discard. * Test TX PDU discard.
*/ */
TESTASSERT(test_tx_sdu_discard(normal_init_state, srslte::pdcp_discard_timer_t::ms50, pool, log) == 0); TESTASSERT(test_tx_sdu_discard(normal_init_state, srslte::pdcp_discard_timer_t::ms50, logger) == 0);
return 0; return 0;
} }
// Setup all tests // Setup all tests
int run_all_tests(srslte::byte_buffer_pool* pool) int run_all_tests()
{ {
// Setup log // Setup log
srslte::log_ref log("PDCP LTE Test"); auto& logger = srslog::fetch_basic_logger("PDCP LTE Test", false);
log->set_level(srslte::LOG_LEVEL_DEBUG); logger.set_level(srslog::basic_levels::debug);
log->set_hex_limit(128); logger.set_hex_dump_max_size(128);
TESTASSERT(test_tx_discard_all(pool, log) == 0); TESTASSERT(test_tx_discard_all(logger) == 0);
return 0; return 0;
} }
int main() int main()
{ {
if (run_all_tests(srslte::byte_buffer_pool::get_instance()) != SRSLTE_SUCCESS) { if (run_all_tests() != SRSLTE_SUCCESS) {
fprintf(stderr, "pdcp_lte_tests() failed\n"); fprintf(stderr, "pdcp_lte_tests() failed\n");
return SRSLTE_ERROR; return SRSLTE_ERROR;
} }
srslte::byte_buffer_pool::cleanup();
return SRSLTE_SUCCESS; return SRSLTE_SUCCESS;
} }

@ -236,7 +236,7 @@ void s1ap::handle_s1ap_rx_pdu(srslte::byte_buffer_t* pdu, struct sctp_sndrcvinfo
// TODO handle_unsuccessfuloutcome(&rx_pdu.choice.unsuccessfulOutcome); // TODO handle_unsuccessfuloutcome(&rx_pdu.choice.unsuccessfulOutcome);
break; break;
default: default:
m_logger.error("Unhandled PDU type %d", rx_pdu.type().value); m_logger.warning("Unhandled PDU type %d", rx_pdu.type().value);
} }
} }

Loading…
Cancel
Save