mac_nr: pretty-print received/transmitted MAC PDUs in logs

srsenb/src/stack/mac/nr/ue_nr.cc

@@ -58,7 +58,7 @@ void ue_nr::set_tti(uint32_t tti)
 
 int ue_nr::process_pdu(srsran::unique_byte_buffer_t pdu)
 {
-  logger.info(pdu->msg, pdu->N_bytes, "Handling MAC PDU (%d B)", pdu->N_bytes);
+  logger.debug(pdu->msg, pdu->N_bytes, "Handling MAC PDU (%d B)", pdu->N_bytes);
 
   mac_pdu_ul.init_rx(true);
   if (mac_pdu_ul.unpack(pdu->msg, pdu->N_bytes) != SRSRAN_SUCCESS) {
@@ -67,17 +67,17 @@ int ue_nr::process_pdu(srsran::unique_byte_buffer_t pdu)
 
   if (logger.info.enabled()) {
     fmt::memory_buffer str_buffer;
-    // mac_pdu_ul.to_string(str_buffer);
+    mac_pdu_ul.to_string(str_buffer);
     logger.info("0x%x %s", rnti, srsran::to_c_str(str_buffer));
   }
 
   for (uint32_t i = 0; i < mac_pdu_ul.get_num_subpdus(); ++i) {
     srsran::mac_sch_subpdu_nr subpdu = mac_pdu_ul.get_subpdu(i);
-    logger.info("Handling subPDU %d/%d: lcid=%d, sdu_len=%d",
-                i,
-                mac_pdu_ul.get_num_subpdus(),
-                subpdu.get_lcid(),
-                subpdu.get_sdu_length());
+    logger.debug("Handling subPDU %d/%d: lcid=%d, sdu_len=%d",
+                 i,
+                 mac_pdu_ul.get_num_subpdus(),
+                 subpdu.get_lcid(),
+                 subpdu.get_sdu_length());
 
     // Handle MAC CEs
     switch (subpdu.get_lcid()) {
@@ -135,7 +135,7 @@ int ue_nr::generate_pdu(srsran::byte_buffer_t* pdu, uint32_t grant_size)
 
   if (logger.info.enabled()) {
     fmt::memory_buffer str_buffer;
-    // mac_pdu_dl.to_string(str_buffer);
+    mac_pdu_dl.to_string(str_buffer);
     logger.info("0x%x %s", rnti, srsran::to_c_str(str_buffer));
   }
   return SRSRAN_SUCCESS;

srsue/src/stack/mac_nr/demux_nr.cc

@@ -12,6 +12,7 @@
 
 #include "srsue/hdr/stack/mac_nr/demux_nr.h"
 #include "srsran/common/buffer_pool.h"
+#include "srsran/common/string_helpers.h"
 #include "srsran/interfaces/ue_rlc_interfaces.h"
 
 namespace srsue {
@@ -43,21 +44,27 @@ void demux_nr::process_pdus()
 /// Handling of DLSCH PDUs only
 void demux_nr::handle_pdu(srsran::unique_byte_buffer_t pdu)
 {
-  logger.info(pdu->msg, pdu->N_bytes, "Handling MAC PDU (%d B)", pdu->N_bytes);
+  logger.debug(pdu->msg, pdu->N_bytes, "Handling MAC PDU (%d B)", pdu->N_bytes);
 
   rx_pdu.init_rx();
   if (rx_pdu.unpack(pdu->msg, pdu->N_bytes) != SRSRAN_SUCCESS) {
     return;
   }
 
+  if (logger.info.enabled()) {
+    fmt::memory_buffer str_buffer;
+    rx_pdu.to_string(str_buffer);
+    logger.info("%s", srsran::to_c_str(str_buffer));
+  }
+
   for (uint32_t i = 0; i < rx_pdu.get_num_subpdus(); ++i) {
     srsran::mac_sch_subpdu_nr subpdu = rx_pdu.get_subpdu(i);
-    logger.info("Handling subPDU %d/%d: rnti=0x%x lcid=%d, sdu_len=%d",
-                i + 1,
-                rx_pdu.get_num_subpdus(),
-                subpdu.get_c_rnti(),
-                subpdu.get_lcid(),
-                subpdu.get_sdu_length());
+    logger.debug("Handling subPDU %d/%d: rnti=0x%x lcid=%d, sdu_len=%d",
+                 i + 1,
+                 rx_pdu.get_num_subpdus(),
+                 subpdu.get_c_rnti(),
+                 subpdu.get_lcid(),
+                 subpdu.get_sdu_length());
 
     // Handle Timing Advance CE
     switch (subpdu.get_lcid()) {

srsue/src/stack/mac_nr/mux_nr.cc

@@ -127,7 +127,13 @@ srsran::unique_byte_buffer_t mux_nr::get_pdu(uint32_t max_pdu_len)
   // Pack PDU
   tx_pdu.pack();
 
-  logger.debug(phy_tx_pdu->msg, phy_tx_pdu->N_bytes, "Generated MAC PDU (%d B)", phy_tx_pdu->N_bytes);
+  if (logger.info.enabled()) {
+    // log pretty printed PDU
+    fmt::memory_buffer buff;
+    tx_pdu.to_string(buff);
+    logger.info("%s", srsran::to_c_str(buff));
+    logger.debug(phy_tx_pdu->msg, phy_tx_pdu->N_bytes, "Generated MAC PDU (%d B)", phy_tx_pdu->N_bytes);
+  }
 
   return phy_tx_pdu;
 }