From 0a1ae0e4ad890aaeb168d3fe7ad6a4ee6d223681 Mon Sep 17 00:00:00 2001 From: Francisco Date: Tue, 18 May 2021 22:17:18 +0100 Subject: [PATCH] redesign and fix enb rrc message logs --- srsenb/hdr/stack/rrc/rrc.h | 40 ++++---- srsenb/src/stack/rrc/rrc.cc | 137 +++++++++++++++------------ srsenb/src/stack/rrc/rrc_mobility.cc | 4 +- srsenb/src/stack/rrc/rrc_ue.cc | 58 ++++++------ 4 files changed, 128 insertions(+), 111 deletions(-) diff --git a/srsenb/hdr/stack/rrc/rrc.h b/srsenb/hdr/stack/rrc/rrc.h index f11657729..4e0b0c44b 100644 --- a/srsenb/hdr/stack/rrc/rrc.h +++ b/srsenb/hdr/stack/rrc/rrc.h @@ -120,34 +120,27 @@ public: uint32_t get_nof_users(); // logging - typedef enum { Rx = 0, Tx, toS1AP, fromS1AP } direction_t; + enum direction_t { Rx = 0, Tx, toS1AP, fromS1AP }; template - void log_rrc_message(const std::string& source, - const direction_t dir, - const srsran::byte_buffer_t* pdu, - const T& msg, - const std::string& msg_type) - { - log_rrc_message(source, dir, srsran::make_span(*pdu), msg, msg_type); - } - template - void log_rrc_message(const std::string& source, - const direction_t dir, + void log_rrc_message(const direction_t dir, + uint16_t rnti, + uint32_t lcid, srsran::const_byte_span pdu, const T& msg, - const std::string& msg_type) + const char* msg_type) { - static const char* dir_str[] = {"Rx", "Tx", "S1AP Tx", "S1AP Rx"}; + log_rxtx_pdu_impl(dir, rnti, lcid, pdu, msg_type); if (logger.debug.enabled()) { asn1::json_writer json_writer; msg.to_json(json_writer); - logger.debug( - pdu.data(), pdu.size(), "%s - %s %s (%zd B)", source.c_str(), dir_str[dir], msg_type.c_str(), pdu.size()); logger.debug("Content:\n%s", json_writer.to_string().c_str()); - } else if (logger.info.enabled()) { - logger.info("%s - %s %s (%zd B)", source.c_str(), dir_str[dir], msg_type.c_str(), pdu.size()); } } + template + void log_broadcast_rrc_message(uint16_t rnti, srsran::const_byte_span pdu, const T& msg, const char* msg_type) + { + log_rrc_message(Tx, rnti, -1, pdu, msg, msg_type); + } private: class ue; @@ -176,19 +169,22 @@ private: int pack_mcch(); void config_mac(); - void parse_ul_dcch(uint16_t rnti, uint32_t lcid, srsran::unique_byte_buffer_t pdu); - void parse_ul_ccch(uint16_t rnti, srsran::unique_byte_buffer_t pdu); + void parse_ul_dcch(ue& ue, uint32_t lcid, srsran::unique_byte_buffer_t pdu); + void parse_ul_ccch(ue& ue, srsran::unique_byte_buffer_t pdu); void send_rrc_connection_reject(uint16_t rnti); const static int mcch_payload_len = 3000; int current_mcch_length = 0; uint8_t mcch_payload_buffer[mcch_payload_len] = {}; - typedef struct { + struct rrc_pdu { uint16_t rnti; uint32_t lcid; uint32_t arg; srsran::unique_byte_buffer_t pdu; - } rrc_pdu; + }; + void log_rx_pdu_fail(uint16_t rnti, uint32_t lcid, srsran::const_byte_span pdu, const char* cause); + void + log_rxtx_pdu_impl(direction_t dir, uint16_t rnti, uint32_t lcid, srsran::const_byte_span pdu, const char* msg_type); const static uint32_t LCID_EXIT = 0xffff0000; const static uint32_t LCID_REM_USER = 0xffff0001; diff --git a/srsenb/src/stack/rrc/rrc.cc b/srsenb/src/stack/rrc/rrc.cc index 07772c0bb..c9144c88b 100644 --- a/srsenb/src/stack/rrc/rrc.cc +++ b/srsenb/src/stack/rrc/rrc.cc @@ -18,6 +18,7 @@ #include "srsran/asn1/rrc_utils.h" #include "srsran/common/bcd_helpers.h" #include "srsran/common/standard_streams.h" +#include "srsran/common/string_helpers.h" #include "srsran/interfaces/enb_mac_interfaces.h" #include "srsran/interfaces/enb_pdcp_interfaces.h" #include "srsran/interfaces/enb_rlc_interfaces.h" @@ -261,9 +262,8 @@ void rrc::send_rrc_connection_reject(uint16_t rnti) } pdu->N_bytes = bref.distance_bytes(); - char buf[32] = {}; - sprintf(buf, "SRB0 - rnti=0x%x", rnti); - log_rrc_message(buf, Tx, pdu.get(), dl_ccch_msg, dl_ccch_msg.msg.c1().type().to_string()); + log_rrc_message(Tx, rnti, srb_to_lcid(lte_srb::srb0), *pdu, dl_ccch_msg, dl_ccch_msg.msg.c1().type().to_string()); + rlc->write_sdu(rnti, srb_to_lcid(lte_srb::srb0), std::move(pdu)); } @@ -479,7 +479,7 @@ void rrc::read_pdu_pcch(uint32_t tti_tx_dl, uint8_t* payload, uint32_t buffer_si logger.info("Assembling PCCH payload with %d UE identities, payload_len=%d bytes", msg.msg.c1().paging().paging_record_list.size(), pdu.size()); - log_rrc_message("PCCH-Message", Tx, pdu, msg, msg.msg.c1().type().to_string()); + log_broadcast_rrc_message(SRSRAN_PRNTI, pdu, msg, msg.msg.c1().type().to_string()); } return true; }; @@ -515,55 +515,44 @@ void rrc::set_erab_status(uint16_t rnti, const asn1::s1ap::bearers_subject_to_st from either a public function or the internal thread *******************************************************************************/ -void rrc::parse_ul_ccch(uint16_t rnti, srsran::unique_byte_buffer_t pdu) +void rrc::parse_ul_ccch(ue& ue, srsran::unique_byte_buffer_t pdu) { - if (pdu) { - ul_ccch_msg_s ul_ccch_msg; - asn1::cbit_ref bref(pdu->msg, pdu->N_bytes); - if (ul_ccch_msg.unpack(bref) != asn1::SRSASN_SUCCESS or - ul_ccch_msg.msg.type().value != ul_ccch_msg_type_c::types_opts::c1) { - logger.error("Failed to unpack UL-CCCH message"); - return; - } + srsran_assert(pdu != nullptr, "parse_ul_ccch called for empty message"); - log_rrc_message("SRB0", Rx, pdu.get(), ul_ccch_msg, ul_ccch_msg.msg.c1().type().to_string()); - - auto user_it = users.find(rnti); - switch (ul_ccch_msg.msg.c1().type().value) { - case ul_ccch_msg_type_c::c1_c_::types::rrc_conn_request: - if (user_it != users.end()) { - user_it->second->save_ul_message(std::move(pdu)); - user_it->second->handle_rrc_con_req(&ul_ccch_msg.msg.c1().rrc_conn_request()); - } else { - logger.error("Received ConnectionSetup for rnti=0x%x without context", rnti); - } - break; - case ul_ccch_msg_type_c::c1_c_::types::rrc_conn_reest_request: - if (user_it != users.end()) { - user_it->second->save_ul_message(std::move(pdu)); - user_it->second->handle_rrc_con_reest_req(&ul_ccch_msg.msg.c1().rrc_conn_reest_request()); - } else { - logger.error("Received ConnectionReestablishment for rnti=0x%x without context.", rnti); - } - break; - default: - logger.error("UL CCCH message not recognised"); - break; - } + ul_ccch_msg_s ul_ccch_msg; + asn1::cbit_ref bref(pdu->msg, pdu->N_bytes); + if (ul_ccch_msg.unpack(bref) != asn1::SRSASN_SUCCESS or + ul_ccch_msg.msg.type().value != ul_ccch_msg_type_c::types_opts::c1) { + log_rx_pdu_fail(ue.rnti, srb_to_lcid(lte_srb::srb0), *pdu, "Failed to unpack UL-CCCH message"); + return; + } + + // Log Rx message + log_rrc_message( + Rx, ue.rnti, srsran::srb_to_lcid(lte_srb::srb0), *pdu, ul_ccch_msg, ul_ccch_msg.msg.c1().type().to_string()); + + switch (ul_ccch_msg.msg.c1().type().value) { + case ul_ccch_msg_type_c::c1_c_::types::rrc_conn_request: + ue.save_ul_message(std::move(pdu)); + ue.handle_rrc_con_req(&ul_ccch_msg.msg.c1().rrc_conn_request()); + break; + case ul_ccch_msg_type_c::c1_c_::types::rrc_conn_reest_request: + ue.save_ul_message(std::move(pdu)); + ue.handle_rrc_con_reest_req(&ul_ccch_msg.msg.c1().rrc_conn_reest_request()); + break; + default: + logger.error("Processing UL-CCCH for rnti=0x%x - Unsupported message type %s", + ul_ccch_msg.msg.c1().type().to_string()); + break; } } ///< User mutex must be hold by caller -void rrc::parse_ul_dcch(uint16_t rnti, uint32_t lcid, srsran::unique_byte_buffer_t pdu) -{ - if (pdu) { - auto user_it = users.find(rnti); - if (user_it != users.end()) { - user_it->second->parse_ul_dcch(lcid, std::move(pdu)); - } else { - logger.error("Processing %s: Unknown rnti=0x%x", get_rb_name(lcid), rnti); - } - } +void rrc::parse_ul_dcch(ue& ue, uint32_t lcid, srsran::unique_byte_buffer_t pdu) +{ + srsran_assert(pdu != nullptr, "parse_ul_dcch called for empty message"); + + ue.parse_ul_dcch(lcid, std::move(pdu)); } ///< User mutex must be hold by caller @@ -743,9 +732,13 @@ uint32_t rrc::generate_sibs() cell_ctxt->sib_buffer.push_back(std::move(sib_buffer)); // Log SIBs in JSON format - std::string log_msg("CC" + std::to_string(cc_idx) + " SIB payload"); - log_rrc_message( - log_msg, Tx, cell_ctxt->sib_buffer.back().get(), msg[msg_index], msg[msg_index].msg.c1().type().to_string()); + fmt::memory_buffer membuf; + const char* msg_str = msg[msg_index].msg.c1().type().to_string(); + if (msg[msg_index].msg.c1().type().value != asn1::rrc::bcch_dl_sch_msg_type_c::c1_c_::types_opts::sib_type1) { + msg_str = msg[msg_index].msg.c1().sys_info().crit_exts.type().to_string(); + } + fmt::format_to(membuf, "{}, cc={}", msg_str, cc_idx); + log_broadcast_rrc_message(SRSRAN_SIRNTI, *cell_ctxt->sib_buffer.back(), msg[msg_index], srsran::to_c_str(membuf)); } if (cfg.sibs[6].type() == asn1::rrc::sys_info_r8_ies_s::sib_type_and_info_item_c_::types::sib7) { @@ -907,26 +900,26 @@ void rrc::tti_clock() // pop cmds from queue rrc_pdu p; while (rx_pdu_queue.try_pop(p)) { - // print Rx PDU - if (p.pdu != nullptr) { - logger.info(p.pdu->msg, p.pdu->N_bytes, "Rx %s PDU", get_rb_name(p.lcid)); - } - // check if user exists auto user_it = users.find(p.rnti); if (user_it == users.end()) { - logger.warning("Discarding PDU for removed rnti=0x%x", p.rnti); + if (p.pdu != nullptr) { + log_rx_pdu_fail(p.rnti, p.lcid, *p.pdu, "unknown rnti"); + } else { + logger.warning("Ignoring rnti=0x%x command. Cause: unknown rnti", p.rnti); + } continue; } + ue& ue = *user_it->second; // handle queue cmd switch (p.lcid) { case srb_to_lcid(lte_srb::srb0): - parse_ul_ccch(p.rnti, std::move(p.pdu)); + parse_ul_ccch(ue, std::move(p.pdu)); break; case srb_to_lcid(lte_srb::srb1): case srb_to_lcid(lte_srb::srb2): - parse_ul_dcch(p.rnti, p.lcid, std::move(p.pdu)); + parse_ul_dcch(ue, p.lcid, std::move(p.pdu)); break; case LCID_REM_USER: rem_user(p.rnti); @@ -956,4 +949,32 @@ void rrc::tti_clock() } } +void rrc::log_rx_pdu_fail(uint16_t rnti, uint32_t lcid, srsran::const_byte_span pdu, const char* cause_str) +{ + logger.error( + pdu.data(), pdu.size(), "Rx %s PDU, rnti=0x%x - Discarding. Cause: %s", get_rb_name(lcid), rnti, cause_str); +} + +void rrc::log_rxtx_pdu_impl(direction_t dir, + uint16_t rnti, + uint32_t lcid, + srsran::const_byte_span pdu, + const char* msg_type) +{ + static const char* dir_str[] = {"Rx", "Tx", "Tx S1AP", "Rx S1AP"}; + fmt::memory_buffer membuf; + fmt::format_to(membuf, "{} ", dir_str[dir]); + if (rnti != SRSRAN_PRNTI and rnti != SRSRAN_SIRNTI) { + if (dir == Tx or dir == Rx) { + fmt::format_to(membuf, "{} ", srsran::get_srb_name(srsran::lte_lcid_to_srb(lcid))); + } + fmt::format_to(membuf, "PDU, rnti=0x{:x} ", rnti); + } else { + fmt::format_to(membuf, "Broadcast PDU "); + } + fmt::format_to(membuf, "- {} ({} B)", msg_type, pdu.size()); + + logger.info(pdu.data(), pdu.size(), "%s", srsran::to_c_str(membuf)); +} + } // namespace srsenb diff --git a/srsenb/src/stack/rrc/rrc_mobility.cc b/srsenb/src/stack/rrc/rrc_mobility.cc index 3214dca5f..797def2b9 100644 --- a/srsenb/src/stack/rrc/rrc_mobility.cc +++ b/srsenb/src/stack/rrc/rrc_mobility.cc @@ -732,7 +732,7 @@ void rrc::ue::rrc_mobility::handle_ho_requested(idle_st& s, const ho_req_rx_ev& trigger(ho_failure_ev{cause}); return; } - rrc_enb->log_rrc_message("HandoverPreparation", direction_t::fromS1AP, rrc_container, hoprep, "HandoverPreparation"); + rrc_enb->log_rrc_message(direction_t::fromS1AP, rrc_ue->rnti, -1, rrc_container, hoprep, "HandoverPreparation"); /* Setup UE current state in TeNB based on HandoverPreparation message */ const ho_prep_info_r8_ies_s& hoprep_r8 = hoprep.crit_exts.c1().ho_prep_info_r8(); @@ -779,7 +779,7 @@ void rrc::ue::rrc_mobility::handle_ho_requested(idle_st& s, const ho_req_rx_ev& return; } ho_cmd_pdu->N_bytes = bref2.distance_bytes(); - rrc_enb->log_rrc_message("RRC container", direction_t::toS1AP, ho_cmd_pdu.get(), dl_dcch_msg, "HandoverCommand"); + rrc_enb->log_rrc_message(direction_t::toS1AP, rrc_ue->rnti, -1, *ho_cmd_pdu, dl_dcch_msg, "HandoverCommand"); asn1::rrc::ho_cmd_s ho_cmd; asn1::rrc::ho_cmd_r8_ies_s& ho_cmd_r8 = ho_cmd.crit_exts.set_c1().set_ho_cmd_r8(); diff --git a/srsenb/src/stack/rrc/rrc_ue.cc b/srsenb/src/stack/rrc/rrc_ue.cc index affb72742..10bb55d72 100644 --- a/srsenb/src/stack/rrc/rrc_ue.cc +++ b/srsenb/src/stack/rrc/rrc_ue.cc @@ -273,11 +273,12 @@ void rrc::ue::parse_ul_dcch(uint32_t lcid, srsran::unique_byte_buffer_t pdu) asn1::cbit_ref bref(pdu->msg, pdu->N_bytes); if (ul_dcch_msg.unpack(bref) != asn1::SRSASN_SUCCESS or ul_dcch_msg.msg.type().value != ul_dcch_msg_type_c::types_opts::c1) { - parent->logger.error("Failed to unpack UL-DCCH message"); + parent->log_rx_pdu_fail(rnti, lcid, *pdu, "Failed to unpack UL-DCCH message"); return; } - parent->log_rrc_message(get_rb_name(lcid), Rx, pdu.get(), ul_dcch_msg, ul_dcch_msg.msg.c1().type().to_string()); + // Log Rx message + parent->log_rrc_message(Rx, rnti, lcid, *pdu, ul_dcch_msg, ul_dcch_msg.msg.c1().type().to_string()); srsran::unique_byte_buffer_t original_pdu = std::move(pdu); pdu = srsran::make_byte_buffer(); @@ -1148,9 +1149,9 @@ void rrc::ue::send_dl_ccch(dl_ccch_msg_s* dl_ccch_msg, std::string* octet_str) } pdu->N_bytes = (uint32_t)bref.distance_bytes(); - char buf[32] = {}; - sprintf(buf, "SRB0 - rnti=0x%x", rnti); - parent->log_rrc_message(buf, Tx, pdu.get(), *dl_ccch_msg, dl_ccch_msg->msg.c1().type().to_string()); + // Log Tx message + parent->log_rrc_message( + Tx, rnti, srb_to_lcid(lte_srb::srb0), *pdu, *dl_ccch_msg, dl_ccch_msg->msg.c1().type().to_string()); // Encode the pdu as an octet string if the user passed a valid pointer. if (octet_str) { @@ -1165,38 +1166,37 @@ void rrc::ue::send_dl_ccch(dl_ccch_msg_s* dl_ccch_msg, std::string* octet_str) bool rrc::ue::send_dl_dcch(const dl_dcch_msg_s* dl_dcch_msg, srsran::unique_byte_buffer_t pdu, std::string* octet_str) { - if (!pdu) { + if (pdu == nullptr) { pdu = srsran::make_byte_buffer(); - } - if (pdu) { - asn1::bit_ref bref(pdu->msg, pdu->get_tailroom()); - if (dl_dcch_msg->pack(bref) == asn1::SRSASN_ERROR_ENCODE_FAIL) { - parent->logger.error("Failed to encode DL-DCCH-Msg"); + if (pdu == nullptr) { + parent->logger.error("Allocating pdu"); return false; } - pdu->N_bytes = (uint32_t)bref.distance_bytes(); + } - lte_srb rb = lte_srb::srb1; - if (dl_dcch_msg->msg.c1().type() == dl_dcch_msg_type_c::c1_c_::types_opts::dl_info_transfer) { - // send messages with NAS on SRB2 if user is fully registered (after RRC reconfig complete) - rb = (parent->rlc->has_bearer(rnti, srb_to_lcid(lte_srb::srb2)) && state == RRC_STATE_REGISTERED) ? lte_srb::srb2 - : lte_srb::srb1; - } + asn1::bit_ref bref(pdu->msg, pdu->get_tailroom()); + if (dl_dcch_msg->pack(bref) == asn1::SRSASN_ERROR_ENCODE_FAIL) { + parent->logger.error("Failed to encode DL-DCCH-Msg for rnti=0x%x", rnti); + return false; + } + pdu->N_bytes = (uint32_t)bref.distance_bytes(); - char buf[32] = {}; - sprintf(buf, "%s - rnti=0x%x", srsran::get_srb_name(rb), rnti); - parent->log_rrc_message(buf, Tx, pdu.get(), *dl_dcch_msg, dl_dcch_msg->msg.c1().type().to_string()); + lte_srb rb = lte_srb::srb1; + if (dl_dcch_msg->msg.c1().type() == dl_dcch_msg_type_c::c1_c_::types_opts::dl_info_transfer) { + // send messages with NAS on SRB2 if user is fully registered (after RRC reconfig complete) + rb = (parent->rlc->has_bearer(rnti, srb_to_lcid(lte_srb::srb2)) && state == RRC_STATE_REGISTERED) ? lte_srb::srb2 + : lte_srb::srb1; + } - // Encode the pdu as an octet string if the user passed a valid pointer. - if (octet_str) { - *octet_str = asn1::octstring_to_string(pdu->msg, pdu->N_bytes); - } + // Log Tx message + parent->log_rrc_message(Tx, rnti, srb_to_lcid(rb), *pdu, *dl_dcch_msg, dl_dcch_msg->msg.c1().type().to_string()); - parent->pdcp->write_sdu(rnti, srb_to_lcid(rb), std::move(pdu)); - } else { - parent->logger.error("Allocating pdu"); - return false; + // Encode the pdu as an octet string if the user passed a valid pointer. + if (octet_str != nullptr) { + *octet_str = asn1::octstring_to_string(pdu->msg, pdu->N_bytes); } + + parent->pdcp->write_sdu(rnti, srb_to_lcid(rb), std::move(pdu)); return true; }