From 20e341d0a1255925662f7b56163d3f2a961b9a77 Mon Sep 17 00:00:00 2001 From: Francisco Date: Tue, 9 Mar 2021 14:44:24 +0000 Subject: [PATCH] mac,bugfix - fixed formatting of MAC and scheduler user-defined types --- lib/include/srslte/adt/interval.h | 22 ++-- lib/include/srslte/common/string_helpers.h | 1 + lib/test/mac/pdu_test.cc | 6 +- srsenb/hdr/stack/mac/sched_common.h | 9 ++ srsenb/src/stack/mac/sched_carrier.cc | 19 ++-- srsenb/src/stack/mac/sched_grid.cc | 120 ++++++++++++--------- srsenb/src/stack/mac/ue.cc | 17 +-- srsenb/test/mac/sched_common_test_suite.cc | 4 +- srsue/src/stack/mac/demux.cc | 3 +- srsue/src/stack/mac/mux.cc | 3 +- 10 files changed, 122 insertions(+), 82 deletions(-) diff --git a/lib/include/srslte/adt/interval.h b/lib/include/srslte/adt/interval.h index 3f29b4722..b0c4761b4 100644 --- a/lib/include/srslte/adt/interval.h +++ b/lib/include/srslte/adt/interval.h @@ -77,8 +77,6 @@ public: bool contains(T point) const { return start_ <= point and point < stop_; } - std::string to_string() const { return fmt::format("[{},{})", start_, stop_); } - private: T start_; T stop_; @@ -134,13 +132,19 @@ interval make_intersection(const interval& lhs, const interval& rhs) return lhs & rhs; } -template -std::ostream& operator<<(std::ostream& out, const interval& interv) -{ - out << interv.to_string(); - return out; -} - } // namespace srslte +namespace fmt { + +template +struct formatter > : public formatter { + template + auto format(const srslte::interval& interv, FormatContext& ctx) -> decltype(std::declval().out()) + { + return format_to(ctx.out(), "[{}, {})", interv.start(), interv.stop()); + } +}; + +} // namespace fmt + #endif // SRSLTE_INTERVAL_H diff --git a/lib/include/srslte/common/string_helpers.h b/lib/include/srslte/common/string_helpers.h index d51ff26fd..190ba2a12 100644 --- a/lib/include/srslte/common/string_helpers.h +++ b/lib/include/srslte/common/string_helpers.h @@ -13,6 +13,7 @@ #ifndef SRSLTE_STRING_HELPERS_H #define SRSLTE_STRING_HELPERS_H +#include "srslte/srslog/bundled/fmt/format.h" #include #include #include diff --git a/lib/test/mac/pdu_test.cc b/lib/test/mac/pdu_test.cc index 2cdd536da..cd3d4fca5 100644 --- a/lib/test/mac/pdu_test.cc +++ b/lib/test/mac/pdu_test.cc @@ -508,7 +508,7 @@ int mac_sch_pdu_pack_test6() } fmt::memory_buffer str_buffer; pdu.to_string(str_buffer); - mac_logger.info("%s", str_buffer.data()); + mac_logger.info("%s", fmt::to_string(str_buffer)); // log mac_logger.info(buffer.msg, buffer.N_bytes, "MAC PDU (%d B):", buffer.N_bytes); @@ -539,7 +539,7 @@ int mac_sch_pdu_pack_test6() pdu.write_packet(mac_logger); str_buffer.clear(); pdu.to_string(str_buffer); - mac_logger.info("%s", str_buffer.data()); + mac_logger.info("%s", fmt::to_string(str_buffer)); TESTASSERT(memcmp(buffer.msg, tv2, buffer.N_bytes) == 0); @@ -594,7 +594,7 @@ int mac_sch_pdu_pack_test6() pdu.write_packet(mac_logger); str_buffer.clear(); pdu.to_string(str_buffer); - mac_logger.info("%s", str_buffer.data()); + mac_logger.info("%s", fmt::to_string(str_buffer)); TESTASSERT(memcmp(buffer.msg, tv3, buffer.N_bytes) == 0); diff --git a/srsenb/hdr/stack/mac/sched_common.h b/srsenb/hdr/stack/mac/sched_common.h index 905f5257f..12a908e5d 100644 --- a/srsenb/hdr/stack/mac/sched_common.h +++ b/srsenb/hdr/stack/mac/sched_common.h @@ -109,4 +109,13 @@ enum class alloc_type_t { DL_BC, DL_PCCH, DL_RAR, DL_DATA, UL_DATA }; } // namespace srsenb +namespace fmt { + +template <> +struct formatter : public formatter > {}; +template <> +struct formatter : public formatter > {}; + +} // namespace fmt + #endif // SRSLTE_SCHED_COMMON_H diff --git a/srsenb/src/stack/mac/sched_carrier.cc b/srsenb/src/stack/mac/sched_carrier.cc index a871f1c8c..0b6928a64 100644 --- a/srsenb/src/stack/mac/sched_carrier.cc +++ b/srsenb/src/stack/mac/sched_carrier.cc @@ -15,6 +15,7 @@ #include "srsenb/hdr/stack/mac/schedulers/sched_time_pf.h" #include "srsenb/hdr/stack/mac/schedulers/sched_time_rr.h" #include "srslte/common/logmap.h" +#include "srslte/common/string_helpers.h" #include "srslte/interfaces/enb_rrc_interfaces.h" namespace srsenb { @@ -150,16 +151,14 @@ void ra_sched::dl_sched(sf_sched* tti_sched) rar.prach_tti + PRACH_RAR_OFFSET + cc_cfg->cfg.prach_rar_window}; if (not rar_window.contains(tti_tx_dl)) { if (tti_tx_dl >= rar_window.stop()) { - char error_msg[128]; - int len = snprintf(error_msg, - sizeof(error_msg), - "SCHED: Could not transmit RAR within the window (RA=%d, Window=%s, RAR=%d)", - rar.prach_tti.to_uint(), - rar_window.to_string().c_str(), - tti_tx_dl.to_uint()); - error_msg[len] = '\0'; - srslte::console("%s\n", error_msg); - logger.error("%s", error_msg); + fmt::memory_buffer str_buffer; + fmt::format_to(str_buffer, + "SCHED: Could not transmit RAR within the window (RA={}, Window={}, RAR={}", + rar.prach_tti, + rar_window, + tti_tx_dl); + srslte::console("%s\n", srslte::to_c_str(str_buffer)); + logger.error("%s", srslte::to_c_str(str_buffer)); // Remove from pending queue and get next one if window has passed already pending_rars.pop_front(); continue; diff --git a/srsenb/src/stack/mac/sched_grid.cc b/srsenb/src/stack/mac/sched_grid.cc index a7be1f2ee..f2b8d22b6 100644 --- a/srsenb/src/stack/mac/sched_grid.cc +++ b/srsenb/src/stack/mac/sched_grid.cc @@ -13,6 +13,7 @@ #include "srsenb/hdr/stack/mac/sched_grid.h" #include "srsenb/hdr/stack/mac/sched_helpers.h" #include "srslte/common/logmap.h" +#include "srslte/common/string_helpers.h" using srslte::tti_point; @@ -156,9 +157,11 @@ void sf_grid_t::new_tti(tti_point tti_rx_) prbmask_t prach_mask{cc_cfg->nof_prb()}; prach_mask.fill(cc_cfg->cfg.prach_freq_offset, cc_cfg->cfg.prach_freq_offset + 6); reserve_ul_prbs(prach_mask, false); // TODO: set to true once test sib.conf files are updated - fmt::memory_buffer buffer; - prach_mask.to_hex(buffer); - logger.debug("SCHED: Allocated PRACH RBs for tti_tx_ul=%d. Mask: 0x%s", to_tx_ul(tti_rx).to_uint(), buffer.data()); + if (logger.debug.enabled()) { + fmt::memory_buffer buffer; + fmt::format_to(buffer, "SCHED: Allocated PRACH RBs mask={:x} for tti_tx_ul={}", prach_mask, to_tx_ul(tti_rx)); + logger.debug("%s", srslte::to_c_str(buffer)); + } } // internal state @@ -281,12 +284,9 @@ alloc_outcome_t sf_grid_t::reserve_ul_prbs(const prbmask_t& prbmask, bool strict { alloc_outcome_t ret = alloc_outcome_t::SUCCESS; if (strict and (ul_mask & prbmask).any()) { - fmt::memory_buffer ulmask_buffer, prbmask_buffer; - ul_mask.to_hex(ulmask_buffer); - prbmask.to_hex(prbmask_buffer); - logger.error("There was a collision in UL channel. current mask=0x%s, new alloc mask=0x%s", - ulmask_buffer.data(), - prbmask_buffer.data()); + fmt::memory_buffer tmp_buffer; + fmt::format_to(tmp_buffer, "There was a collision in the UL. Current mask={:x}, new mask={:x}", ul_mask, prbmask); + logger.error("%s", srslte::to_c_str(tmp_buffer)); ret = alloc_outcome_t::ERROR; } ul_mask |= prbmask; @@ -738,8 +738,10 @@ void sf_sched::set_bc_sched_result(const sf_cch_allocator::alloc_result_t& dci_r } else { // Paging if (tbs <= 0) { + fmt::memory_buffer str_buffer; + fmt::format_to(str_buffer, "{}", bc_alloc.rbg_range); logger.warning("SCHED: Error Paging, rbgs=%s, dci=(%d,%d)", - bc_alloc.rbg_range.to_string().c_str(), + srslte::to_c_str(str_buffer), bc->dci.location.L, bc->dci.location.ncce); continue; @@ -749,8 +751,10 @@ void sf_sched::set_bc_sched_result(const sf_cch_allocator::alloc_result_t& dci_r bc->type = sched_interface::dl_sched_bc_t::PCCH; bc->tbs = (uint32_t)tbs; + fmt::memory_buffer str_buffer; + fmt::format_to(str_buffer, "{}", bc_alloc.rbg_range); logger.info("SCHED: PCH, rbgs=%s, dci=(%d,%d), tbs=%d, mcs=%d", - bc_alloc.rbg_range.to_string().c_str(), + srslte::to_c_str(str_buffer), bc->dci.location.L, bc->dci.location.ncce, tbs, @@ -774,9 +778,11 @@ void sf_sched::set_rar_sched_result(const sf_cch_allocator::alloc_result_t& dci_ prb_interval prb_range = prb_interval::rbgs_to_prbs(rar_alloc.alloc_data.rbg_range, cc_cfg->nof_prb()); int tbs = generate_format1a(prb_range, rar_alloc.alloc_data.req_bytes, 0, rar_alloc.alloc_data.rnti, &rar->dci); if (tbs <= 0) { + fmt::memory_buffer str_buffer; + fmt::format_to(str_buffer, "{}", rar_alloc.alloc_data.rbg_range); logger.warning("SCHED: Error RAR, ra_rnti_idx=%d, rbgs=%s, dci=(%d,%d)", rar_alloc.alloc_data.rnti, - rar_alloc.alloc_data.rbg_range.to_string().c_str(), + srslte::to_c_str(str_buffer), rar->dci.location.L, rar->dci.location.ncce); continue; @@ -788,13 +794,15 @@ void sf_sched::set_rar_sched_result(const sf_cch_allocator::alloc_result_t& dci_ // Print RAR allocation result for (uint32_t i = 0; i < rar->msg3_grant.size(); ++i) { - const auto& msg3_grant = rar->msg3_grant[i]; - uint16_t expected_rnti = msg3_grant.data.temp_crnti; + const auto& msg3_grant = rar->msg3_grant[i]; + uint16_t expected_rnti = msg3_grant.data.temp_crnti; + fmt::memory_buffer str_buffer; + fmt::format_to(str_buffer, "{}", rar_alloc.alloc_data.rbg_range); logger.info("SCHED: RAR, temp_crnti=0x%x, ra-rnti=%d, rbgs=%s, dci=(%d,%d), rar_grant_rba=%d, " "rar_grant_mcs=%d", expected_rnti, rar_alloc.alloc_data.rnti, - rar_alloc.alloc_data.rbg_range.to_string().c_str(), + srslte::to_c_str(str_buffer), rar->dci.location.L, rar->dci.location.ncce, msg3_grant.grant.rba, @@ -829,33 +837,35 @@ void sf_sched::set_dl_data_sched_result(const sf_cch_allocator::alloc_result_t& data_alloc.pid, data, get_tti_tx_dl(), cc_cfg->enb_cc_idx, tti_alloc.get_cfi(), data_alloc.user_mask); if (tbs <= 0) { - fmt::memory_buffer buffer; - data_alloc.user_mask.to_hex(buffer); - logger.warning("SCHED: DL %s failed rnti=0x%x, pid=%d, mask=%s, tbs=%d, buffer=%d", + fmt::memory_buffer str_buffer; + fmt::format_to(str_buffer, + "SCHED: DL {} failed rnti=0x{:x}, pid={}, mask={:x}, tbs={}, buffer={}", is_newtx ? "tx" : "retx", user->get_rnti(), data_alloc.pid, - buffer.data(), + data_alloc.user_mask, tbs, user->get_requested_dl_bytes(cc_cfg->enb_cc_idx).stop()); + logger.warning("%s", srslte::to_c_str(str_buffer)); continue; } // Print Resulting DL Allocation - fmt::memory_buffer buffer; - data_alloc.user_mask.to_hex(buffer); - logger.info("SCHED: DL %s rnti=0x%x, cc=%d, pid=%d, mask=%s, dci=(%d,%d), n_rtx=%d, tbs=%d, buffer=%d/%d", - !is_newtx ? "retx" : "tx", - user->get_rnti(), - cc_cfg->enb_cc_idx, - data_alloc.pid, - buffer.data(), - data->dci.location.L, - data->dci.location.ncce, - dl_harq.nof_retx(0) + dl_harq.nof_retx(1), - tbs, - data_before, - user->get_requested_dl_bytes(cc_cfg->enb_cc_idx).stop()); + fmt::memory_buffer str_buffer; + fmt::format_to(str_buffer, + "SCHED: DL {} rnti=0x{:x}, cc={}, pid={}, mask={:x}, dci=({}, {}), n_rtx={}, tbs={}, buffer={}/{}", + is_newtx ? "tx" : "retx", + user->get_rnti(), + cc_cfg->enb_cc_idx, + data_alloc.pid, + data_alloc.user_mask, + data->dci.location.L, + data->dci.location.ncce, + dl_harq.nof_retx(0) + dl_harq.nof_retx(1), + tbs, + data_before, + user->get_requested_dl_bytes(cc_cfg->enb_cc_idx).stop()); + logger.info("%s", srslte::to_c_str(str_buffer)); dl_result->nof_data_elems++; } @@ -984,34 +994,42 @@ void sf_sched::set_ul_sched_result(const sf_cch_allocator::alloc_result_t& dci_r uint32_t new_pending_bytes = user->get_pending_ul_new_data(get_tti_tx_ul(), cc_cfg->enb_cc_idx); // Allow TBS=0 in case of UCI-only PUSCH if (tbs < 0 || (tbs == 0 && pusch->dci.tb.mcs_idx != 29)) { - logger.warning("SCHED: Error %s %s rnti=0x%x, pid=%d, dci=(%d,%d), prb=%s, bsr=%d", + fmt::memory_buffer str_buffer; + fmt::format_to(str_buffer, + "SCHED: Error {} {} rnti=0x{:x}, pid={}, dci=({},{}), prb={}, bsr={}", ul_alloc.type == ul_alloc_t::MSG3 ? "Msg3" : "UL", ul_alloc.is_retx() ? "retx" : "tx", user->get_rnti(), h->get_id(), pusch->dci.location.L, pusch->dci.location.ncce, - ul_alloc.alloc.to_string().c_str(), + ul_alloc.alloc, new_pending_bytes); + logger.warning("%s", srslte::to_c_str(str_buffer)); continue; } // Print Resulting UL Allocation uint32_t old_pending_bytes = user->get_pending_ul_old_data(); - logger.info("SCHED: %s %s rnti=0x%x, cc=%d, pid=%d, dci=(%d,%d), prb=%s, n_rtx=%d, tbs=%d, bsr=%d (%d-%d)", - ul_alloc.is_msg3() ? "Msg3" : "UL", - ul_alloc.is_retx() ? "retx" : "tx", - user->get_rnti(), - cc_cfg->enb_cc_idx, - h->get_id(), - pusch->dci.location.L, - pusch->dci.location.ncce, - ul_alloc.alloc.to_string().c_str(), - h->nof_retx(0), - tbs, - new_pending_bytes, - total_data_before, - old_pending_bytes); + if (logger.info.enabled()) { + fmt::memory_buffer str_buffer; + fmt::format_to(str_buffer, + "SCHED: {} {} rnti=0x{:x}, cc={}, pid={}, dci=({},{}), prb={}, n_rtx={}, tbs={}, bsr={} ({}-{})", + ul_alloc.is_msg3() ? "Msg3" : "UL", + ul_alloc.is_retx() ? "retx" : "newtx", + user->get_rnti(), + cc_cfg->enb_cc_idx, + h->get_id(), + pusch->dci.location.L, + pusch->dci.location.ncce, + ul_alloc.alloc, + h->nof_retx(0), + tbs, + new_pending_bytes, + total_data_before, + old_pending_bytes); + logger.info("%s", srslte::to_c_str(str_buffer)); + } pusch->current_tx_nb = h->nof_retx(0); @@ -1026,7 +1044,9 @@ alloc_outcome_t sf_sched::alloc_msg3(sched_ue* user, const sched_interface::dl_s alloc_outcome_t ret = alloc_ul(user, msg3_alloc, sf_sched::ul_alloc_t::MSG3, rargrant.grant.trunc_mcs); if (not ret) { - logger.warning("SCHED: Could not allocate msg3 within %s", msg3_alloc.to_string().c_str()); + fmt::memory_buffer str_buffer; + fmt::format_to(str_buffer, "{}", msg3_alloc); + logger.warning("SCHED: Could not allocate msg3 within %s", srslte::to_c_str(str_buffer)); } return ret; } diff --git a/srsenb/src/stack/mac/ue.cc b/srsenb/src/stack/mac/ue.cc index 09bbedc8f..157c23e45 100644 --- a/srsenb/src/stack/mac/ue.cc +++ b/srsenb/src/stack/mac/ue.cc @@ -16,6 +16,7 @@ #include #include "srsenb/hdr/stack/mac/ue.h" +#include "srslte/common/string_helpers.h" #include "srslte/interfaces/enb_phy_interfaces.h" #include "srslte/interfaces/enb_rlc_interfaces.h" #include "srslte/interfaces/enb_rrc_interfaces.h" @@ -255,9 +256,11 @@ void ue::process_pdu(uint8_t* pdu, uint32_t nof_bytes, srslte::pdu_queue::channe mac_msg_ul.init_rx(nof_bytes, true); mac_msg_ul.parse_packet(pdu); - fmt::memory_buffer buffer; - mac_msg_ul.to_string(buffer); - logger.info("0x%x %s", rnti, buffer.data()); + if (logger.info.enabled()) { + fmt::memory_buffer str_buffer; + mac_msg_ul.to_string(str_buffer); + logger.info("0x%x %s", rnti, srslte::to_c_str(str_buffer)); + } if (pcap) { pcap->write_ul_crnti(pdu, nof_bytes, rnti, true, last_tti, UL_CC_IDX); @@ -531,9 +534,11 @@ uint8_t* ue::generate_pdu(uint32_t ue_cc_idx, } } ret = mac_msg_dl.write_packet(logger); - fmt::memory_buffer str_buffer; - mac_msg_dl.to_string(str_buffer); - logger.info("0x%x %s", rnti, str_buffer.data()); + if (logger.info.enabled()) { + fmt::memory_buffer str_buffer; + mac_msg_dl.to_string(str_buffer); + logger.info("0x%x %s", rnti, srslte::to_c_str(str_buffer)); + } } else { logger.error( "Invalid parameters calling generate_pdu: cc_idx=%d, harq_pid=%d, tb_idx=%d", ue_cc_idx, harq_pid, tb_idx); diff --git a/srsenb/test/mac/sched_common_test_suite.cc b/srsenb/test/mac/sched_common_test_suite.cc index 2d9f2b787..1e9f68710 100644 --- a/srsenb/test/mac/sched_common_test_suite.cc +++ b/srsenb/test/mac/sched_common_test_suite.cc @@ -26,12 +26,12 @@ int test_pusch_collisions(const sf_output_res_t& sf_out, uint32_t enb_cc_idx, co prbmask_t ul_allocs(nof_prb); auto try_ul_fill = [&](prb_interval alloc, const char* ch_str, bool strict = true) { - CONDERROR(alloc.stop() > nof_prb, "Allocated RBs %s out-of-bounds", alloc.to_string().c_str()); + CONDERROR(alloc.stop() > nof_prb, "Allocated RBs %s out-of-bounds", fmt::format("{}", alloc).c_str()); CONDERROR(alloc.empty(), "Allocations must have at least one PRB"); if (strict and ul_allocs.any(alloc.start(), alloc.stop())) { TESTERROR("Collision Detected of %s alloc=%s and cumulative_mask=0x%s", ch_str, - alloc.to_string().c_str(), + fmt::format("{}", alloc).c_str(), fmt::format("{:x}", ul_allocs).c_str()); } ul_allocs.fill(alloc.start(), alloc.stop(), true); diff --git a/srsue/src/stack/mac/demux.cc b/srsue/src/stack/mac/demux.cc index 995a487f7..c185c02af 100644 --- a/srsue/src/stack/mac/demux.cc +++ b/srsue/src/stack/mac/demux.cc @@ -16,6 +16,7 @@ #define Debug(fmt, ...) logger.debug(fmt, ##__VA_ARGS__) #include "srsue/hdr/stack/mac/demux.h" +#include "srslte/common/string_helpers.h" #include "srslte/interfaces/ue_phy_interfaces.h" namespace srsue { @@ -156,7 +157,7 @@ void demux::process_pdu(uint8_t* mac_pdu, uint32_t nof_bytes, srslte::pdu_queue: { fmt::memory_buffer buffer; mac_msg.to_string(buffer); - Info("%s", buffer.data()); + Info("%s", srslte::to_c_str(buffer)); } process_sch_pdu(&mac_msg); pdus.deallocate(mac_pdu); diff --git a/srsue/src/stack/mac/mux.cc b/srsue/src/stack/mac/mux.cc index 3e8d0f592..26e478e22 100644 --- a/srsue/src/stack/mac/mux.cc +++ b/srsue/src/stack/mac/mux.cc @@ -16,6 +16,7 @@ #define Debug(fmt, ...) logger.debug(fmt, ##__VA_ARGS__) #include "srsue/hdr/stack/mac/mux.h" +#include "srslte/common/string_helpers.h" #include "srsue/hdr/stack/mac/mac.h" #include @@ -288,7 +289,7 @@ uint8_t* mux::pdu_get(srslte::byte_buffer_t* payload, uint32_t pdu_sz) uint8_t* ret = pdu_msg.write_packet(logger); fmt::memory_buffer buffer; pdu_msg.to_string(buffer); - Info("%s", buffer.data()); + Info("%s", srslte::to_c_str(buffer)); Debug("Assembled MAC PDU msg size %d/%d bytes", pdu_msg.get_pdu_len() - pdu_msg.rem_size(), pdu_sz); return ret;