rfnoc: Update logging in some blocks

Updated the following blocks and components: Radio, DmaFIFO,
block_ctrl_base and node_ctrl_base, blockdef_xml_impl, device3_impl.
No functional changes.

- Demoted some log messages
- Consistent log style (use unique_id())
- Some adaptation of coding style where close to log statements

6 files changed, 87 insertions, 56 deletions

diff --git a/host/lib/rfnoc/block_ctrl_base.cpp b/host/lib/rfnoc/block_ctrl_base.cpp
index 20d79d262..246ba7196 100644
--- a/host/lib/rfnoc/block_ctrl_base.cpp
+++ b/host/lib/rfnoc/block_ctrl_base.cpp
@@ -20,8 +20,6 @@
 #include <boost/format.hpp>
 #include <boost/bind.hpp>
 
-#define UHD_BLOCK_LOG() UHD_LOGGER_TRACE("RFNOC")
-
 using namespace uhd;
 using namespace uhd::rfnoc;
 using std::string;
@@ -37,14 +35,16 @@ block_ctrl_base::block_ctrl_base(
     _noc_id(sr_read64(SR_READBACK_REG_ID)),
     _compat_num(sr_read64(SR_READBACK_COMPAT))
 {
-    UHD_BLOCK_LOG() << "block_ctrl_base()" ;
-
     /*** Identify this block (NoC-ID, block-ID, and block definition) *******/
     // Read NoC-ID (name is passed in through make_args):
     _block_def = blockdef::make_from_noc_id(_noc_id);
-    if (_block_def) UHD_BLOCK_LOG() <<  "Found valid blockdef" ;
-    if (not _block_def)
+    if (not _block_def) {
+        UHD_LOG_DEBUG("RFNOC",
+            "No block definition found, using default block configuration "
+            "for block with NOC ID: " + str(boost::format("0x%08X") % noc_id)
+        );
         _block_def = blockdef::make_from_noc_id(DEFAULT_NOC_ID);
+    }
     UHD_ASSERT_THROW(_block_def);
     // For the block ID, we start with block count 0 and increase until
     // we get a block ID that's not already registered:
@@ -52,9 +52,10 @@ block_ctrl_base::block_ctrl_base(
     while (_tree->exists("xbar/" + _block_id.get_local())) {
         _block_id++;
     }
-    UHD_BLOCK_LOG()
-        << "NOC ID: " << str(boost::format("0x%016X  ") % _noc_id)
-        << "Block ID: " << _block_id ;
+    UHD_LOG_INFO(unique_id(), str(
+            boost::format("Initializing block control (NOC ID: 0x%016X)")
+            % _noc_id
+    ));
 
     /*** Check compat number ************************************************/
     assert_fpga_compat(
@@ -62,7 +63,7 @@ block_ctrl_base::block_ctrl_base(
             NOC_SHELL_COMPAT_MINOR,
             _compat_num,
             "noc_shell",
-            "RFNoC",
+            unique_id(),
             false /* fail_on_minor_behind */
     );
 
@@ -75,7 +76,7 @@ block_ctrl_base::block_ctrl_base(
 
     /*** Configure ports ****************************************************/
     size_t n_valid_input_buffers = 0;
-    for(const size_t ctrl_port:  get_ctrl_ports()) {
+    for (const size_t ctrl_port : get_ctrl_ports()) {
         // Set command times to sensible defaults
         set_command_tick_rate(1.0, ctrl_port);
         set_command_time(time_spec_t(0.0), ctrl_port);
@@ -113,10 +114,12 @@ block_ctrl_base::block_ctrl_base(
     _init_port_defs("out", _block_def->get_output_ports());
     // FIXME this warning always fails until the input buffer code above is fixed
     if (_tree->list(_root_path / "ports/in").size() != n_valid_input_buffers) {
-        UHD_LOGGER_WARNING("RFNOC") <<
+        UHD_LOGGER_WARNING(unique_id()) <<
             boost::format("[%s] defines %d input buffer sizes, but %d input ports")
-            % get_block_id().get() % n_valid_input_buffers % _tree->list(_root_path / "ports/in").size()
-            ;
+            % get_block_id().get()
+            % n_valid_input_buffers
+            % _tree->list(_root_path / "ports/in").size()
+        ;
     }
 
     /*** Init default block args ********************************************/
@@ -140,9 +143,13 @@ void block_ctrl_base::_init_port_defs(
         if (not _tree->exists(port_path)) {
             _tree->create<blockdef::port_t>(port_path);
         }
-        UHD_RFNOC_BLOCK_TRACE()  << "Adding port definition at " << port_path
-            << boost::format(": type = '%s' pkt_size = '%s' vlen = '%s'") % port_def["type"] % port_def["pkt_size"] % port_def["vlen"]
-            ;
+        UHD_LOGGER_TRACE(unique_id())
+            << "Adding port definition at " << port_path
+            << boost::format(": type = '%s' pkt_size = '%s' vlen = '%s'")
+                % port_def["type"]
+                % port_def["pkt_size"]
+                % port_def["vlen"]
+        ;
         _tree->access<blockdef::port_t>(port_path).set(port_def);
         port_index++;
     }
@@ -152,12 +159,12 @@ void block_ctrl_base::_init_block_args()
 {
     blockdef::args_t args = _block_def->get_args();
     fs_path arg_path = _root_path / "args";
-    for(const size_t port:  get_ctrl_ports()) {
+    for (const size_t port : get_ctrl_ports()) {
         _tree->create<std::string>(arg_path / port);
     }
 
     // First, create all nodes.
-    for(const blockdef::arg_t &arg:  args) {
+    for (const auto& arg : args) {
         fs_path arg_type_path = arg_path / arg["port"] / arg["name"] / "type";
         _tree->create<std::string>(arg_type_path).set(arg["type"]);
         fs_path arg_val_path  = arg_path / arg["port"] / arg["name"] / "value";
@@ -171,7 +178,7 @@ void block_ctrl_base::_init_block_args()
     // TODO: Add coercer
 #define _SUBSCRIBE_CHECK_AND_RUN(type, arg_tag, error_message) \
     _tree->access<type>(arg_val_path).add_coerced_subscriber(boost::bind((&nocscript::block_iface::run_and_check), _nocscript_iface, arg[#arg_tag], error_message))
-    for(const blockdef::arg_t &arg:  args) {
+    for (const auto& arg : args) {
         fs_path arg_val_path = arg_path / arg["port"] / arg["name"] / "value";
         if (not arg["check"].empty()) {
             if (arg["type"] == "string") { _SUBSCRIBE_CHECK_AND_RUN(string, check, arg["check_message"]); }
@@ -190,7 +197,7 @@ void block_ctrl_base::_init_block_args()
     }
 
     // Finally: Set the values. This will call subscribers, if we have any.
-    for(const blockdef::arg_t &arg:  args) {
+    for (const auto& arg : args) {
         fs_path arg_val_path = arg_path / arg["port"] / arg["name"] / "value";
         if (not arg["value"].empty()) {
             if (arg["type"] == "int_vector") { throw uhd::runtime_error("not yet implemented: int_vector"); }
@@ -228,8 +235,6 @@ std::vector<size_t> block_ctrl_base::get_ctrl_ports() const
 
 void block_ctrl_base::sr_write(const uint32_t reg, const uint32_t data, const size_t port)
 {
-    //UHD_BLOCK_LOG() << "  ";
-    //UHD_RFNOC_BLOCK_TRACE() << boost::format("sr_write(%d, %08X, %d)") % reg % data % port ;
     if (not _ctrl_ifaces.count(port)) {
         throw uhd::key_error(str(boost::format("[%s] sr_write(): No such port: %d") % get_block_id().get() % port));
     }
@@ -258,7 +263,6 @@ void block_ctrl_base::sr_write(const std::string &reg, const uint32_t data, cons
         }
         reg_addr = uint32_t(_tree->access<size_t>(_root_path / "registers" / "sr" / reg).get());
     }
-    UHD_RFNOC_BLOCK_TRACE() << boost::format("sr_write(%s, %08X) ==> ") % reg % data ;
     return sr_write(reg_addr, data, port);
 }
 
@@ -396,11 +400,11 @@ void block_ctrl_base::clear_command_time(const size_t port)
 
 void block_ctrl_base::clear()
 {
-    UHD_RFNOC_BLOCK_TRACE() << "block_ctrl_base::clear() " ;
+    UHD_LOG_TRACE(unique_id(), "block_ctrl_base::clear()");
     // Call parent...
     node_ctrl_base::clear();
     // ...then child
-    for(const size_t port_index:  get_ctrl_ports()) {
+    for (const size_t port_index : get_ctrl_ports()) {
         _clear(port_index);
     }
 }
@@ -519,7 +523,6 @@ stream_sig_t block_ctrl_base::_resolve_port_def(const blockdef::port_t &port_def
     } else {
         stream_sig.item_type = port_def["type"];
     }
-    //UHD_RFNOC_BLOCK_TRACE() << "  item type: " << stream_sig.item_type ;
 
     // Vector length
     if (port_def.is_variable("vlen")) {
@@ -530,7 +533,6 @@ stream_sig_t block_ctrl_base::_resolve_port_def(const blockdef::port_t &port_def
     } else {
         stream_sig.vlen = boost::lexical_cast<size_t>(port_def["vlen"]);
     }
-    //UHD_RFNOC_BLOCK_TRACE() << "  vector length: " << stream_sig.vlen ;
 
     // Packet size
     if (port_def.is_variable("pkt_size")) {
@@ -552,7 +554,6 @@ stream_sig_t block_ctrl_base::_resolve_port_def(const blockdef::port_t &port_def
     } else {
         stream_sig.packet_size = boost::lexical_cast<size_t>(port_def["pkt_size"]);
     }
-    //UHD_RFNOC_BLOCK_TRACE() << "  packet size: " << stream_sig.vlen ;
 
     return stream_sig;
 }
@@ -563,13 +564,13 @@ stream_sig_t block_ctrl_base::_resolve_port_def(const blockdef::port_t &port_def
  **********************************************************************/
 void block_ctrl_base::_clear(const size_t port)
 {
-    UHD_RFNOC_BLOCK_TRACE() << "block_ctrl_base::_clear() " ;
+    UHD_LOG_TRACE(unique_id(), "block_ctrl_base::_clear()");
     sr_write(SR_CLEAR_TX_FC, 0x00C1EA12, port); // 'CLEAR', but we can write anything, really
     sr_write(SR_CLEAR_RX_FC, 0x00C1EA12, port); // 'CLEAR', but we can write anything, really
 }
 
 void block_ctrl_base::_set_command_time(const time_spec_t & /*time_spec*/, const size_t /*port*/)
 {
-    UHD_RFNOC_BLOCK_TRACE() << "block_ctrl_base::_set_command_time() ";
+    UHD_LOG_TRACE(unique_id(), "block_ctrl_base::_set_command_time()");
 }
 // vim: sw=4 et:
diff --git a/host/lib/rfnoc/blockdef_xml_impl.cpp b/host/lib/rfnoc/blockdef_xml_impl.cpp
index d8f749aa0..50faf6905 100644
--- a/host/lib/rfnoc/blockdef_xml_impl.cpp
+++ b/host/lib/rfnoc/blockdef_xml_impl.cpp
@@ -213,7 +213,9 @@ public:
                 }
             }
         } catch (std::exception &e) {
-            UHD_LOGGER_WARNING("RFNOC") << "has_noc_id(): caught exception " << e.what() ;
+            UHD_LOGGER_WARNING("RFNOC")
+                << "has_noc_id(): caught exception " << e.what()
+                << " while parsing file: " << filename.string();
             return false;
         }
         return false;
@@ -223,7 +225,11 @@ public:
         _type(type),
         _noc_id(noc_id)
     {
-        //UHD_LOGGER_INFO("RFNOC") << "Reading XML file: " << filename.string().c_str() ;
+        UHD_LOGGER_DEBUG("RFNOC") <<
+            boost::format("Reading XML file %s for NOC ID 0x%08X")
+            % filename.string().c_str()
+            % noc_id
+        ;
         read_xml(filename.string(), _pt);
         try {
             // Check key is valid
@@ -352,7 +358,8 @@ public:
                 arg["type"] = "string";
             }
             if (not arg.is_valid()) {
-                UHD_LOGGER_WARNING("RFNOC") << boost::format("Found invalid argument: %s") % arg.to_string() ;
+                UHD_LOGGER_WARNING("RFNOC")
+                    << "Found invalid argument: " << arg.to_string();
                 is_valid = false;
             }
             args.push_back(arg);
@@ -408,15 +415,14 @@ blockdef::sptr blockdef::make_from_noc_id(uint64_t noc_id)
     std::vector<fs::path> valid;
 
     // Check if any of the paths exist
-    for(const fs::path &base_path:  paths) {
+    for (const auto& base_path : paths) {
         fs::path this_path = base_path / XML_BLOCKS_SUBDIR;
         if (fs::exists(this_path) and fs::is_directory(this_path)) {
             valid.push_back(this_path);
         }
     }
 
-    if (valid.empty())
-    {
+    if (valid.empty()) {
         throw uhd::assertion_error(
             "Failed to find a valid XML path for RFNoC blocks.\n"
             "Try setting the enviroment variable UHD_RFNOC_DIR "
@@ -425,7 +431,7 @@ blockdef::sptr blockdef::make_from_noc_id(uint64_t noc_id)
     }
 
     // Iterate over all paths
-    for(const fs::path &path:  valid) {
+    for (const auto& path : valid) {
         // Iterate over all .xml files
         fs::directory_iterator end_itr;
         for (fs::directory_iterator i(path); i != end_itr; ++i) {
diff --git a/host/lib/rfnoc/dma_fifo_block_ctrl_impl.cpp b/host/lib/rfnoc/dma_fifo_block_ctrl_impl.cpp
index e27c20809..16ad7db6f 100644
--- a/host/lib/rfnoc/dma_fifo_block_ctrl_impl.cpp
+++ b/host/lib/rfnoc/dma_fifo_block_ctrl_impl.cpp
@@ -34,19 +34,20 @@ public:
             _perifs[i].depth = DEFAULT_SIZE;
             _perifs[i].core = dma_fifo_core_3000::make(_perifs[i].ctrl, USER_SR_BASE, USER_RB_BASE);
             _perifs[i].core->resize(_perifs[i].base_addr, _perifs[i].depth);
-            UHD_LOGGER_INFO("RFNOC DMA FIFO") << boost::format("Running BIST for FIFO %d... ") % i;
+            UHD_LOG_DEBUG(unique_id(), "Running BIST for FIFO " << i);
             if (_perifs[i].core->ext_bist_supported()) {
                 uint32_t bisterr = _perifs[i].core->run_bist();
                 if (bisterr != 0) {
                     throw uhd::runtime_error(str(boost::format("BIST failed! (code: %d)\n") % bisterr));
                 } else {
                     double throughput = _perifs[i].core->get_bist_throughput();
-                    UHD_LOGGER_INFO("RFNOC DMA FIFO") << (boost::format("BIST passed (Throughput: %.0f MB/s)") % (throughput/1e6)) ;
+                    UHD_LOGGER_INFO(unique_id()) << (boost::format("BIST passed (Throughput: %.0f MB/s)") % (throughput/1e6)) ;
                 }
             } else {
                 if (_perifs[i].core->run_bist() == 0) {
-                    UHD_LOGGER_INFO("RFNOC DMA FIFO") << "BIST passed";
+                    UHD_LOGGER_INFO(unique_id()) << "BIST passed";
                 } else {
+                    UHD_LOGGER_ERROR(unique_id()) << "BIST failed!";
                     throw uhd::runtime_error("BIST failed!");
                 }
             }
diff --git a/host/lib/rfnoc/node_ctrl_base.cpp b/host/lib/rfnoc/node_ctrl_base.cpp
index 7828cd514..60496798d 100644
--- a/host/lib/rfnoc/node_ctrl_base.cpp
+++ b/host/lib/rfnoc/node_ctrl_base.cpp
@@ -20,7 +20,7 @@ std::string node_ctrl_base::unique_id() const
 
 void node_ctrl_base::clear()
 {
-    UHD_RFNOC_BLOCK_TRACE() << "node_ctrl_base::clear() " ;
+    UHD_LOG_TRACE(unique_id(), "node_ctrl_base::clear()");
     // Reset connections:
     _upstream_nodes.clear();
     _downstream_nodes.clear();
diff --git a/host/lib/rfnoc/radio_ctrl_impl.cpp b/host/lib/rfnoc/radio_ctrl_impl.cpp
index 5347150ba..2479d889a 100644
--- a/host/lib/rfnoc/radio_ctrl_impl.cpp
+++ b/host/lib/rfnoc/radio_ctrl_impl.cpp
@@ -120,9 +120,10 @@ void radio_ctrl_impl::_register_loopback_self_test(size_t chan)
             return; // exit on any failure
         }
     }
-    UHD_LOGGER_INFO("RFNOC RADIO") << "Register loopback test passed";
+    UHD_LOG_DEBUG(unique_id(), "Register loopback test passed");
 }
 
+
 /****************************************************************************
  * API calls
  ***************************************************************************/
diff --git a/host/lib/usrp/device3/device3_impl.cpp b/host/lib/usrp/device3/device3_impl.cpp
index 6f1719500..772008a38 100644
--- a/host/lib/usrp/device3/device3_impl.cpp
+++ b/host/lib/usrp/device3/device3_impl.cpp
@@ -13,8 +13,6 @@
 #include <boost/make_shared.hpp>
 #include <algorithm>
 
-#define UHD_DEVICE3_LOG() UHD_LOGGER_TRACE("DEVICE3")
-
 using namespace uhd::usrp;
 
 device3_impl::device3_impl()
@@ -108,7 +106,6 @@ void device3_impl::enumerate_rfnoc_blocks(
     // TODO: Clear out all the old block control classes
     // 3) Create new block controllers
     for (size_t i = 0; i < n_blocks; i++) {
-        UHD_DEVICE3_LOG() << "[RFNOC] ------- Block Setup -----------" ;
         // First, make a transport for port number zero, because we always need that:
         ctrl_sid.set_dst_xbarport(base_port + i);
         ctrl_sid.set_dst_blockport(0);
@@ -117,22 +114,39 @@ void device3_impl::enumerate_rfnoc_blocks(
             CTRL,
             transport_args
         );
-        UHD_DEVICE3_LOG() << str(boost::format("Setting up NoC-Shell Control for port #0 (SID: %s)...") % xport.send_sid.to_pp_string_hex());
+        UHD_LOG_TRACE("DEVICE3",
+            str(boost::format("Setting up NoC-Shell Control for port #0 (SID: %s)...")
+                % xport.send_sid.to_pp_string_hex())
+        );
         uhd::rfnoc::ctrl_iface::sptr ctrl = uhd::rfnoc::ctrl_iface::make(
-                xport,
-                str(boost::format("CE_%02d_Port_%02X") % i % ctrl_sid.get_dst_endpoint())
+            xport,
+            str(boost::format("CE_%02d_Port_%02X")
+                % i
+                % ctrl_sid.get_dst_endpoint())
+        );
+        uint64_t noc_id = ctrl->send_cmd_pkt(
+                uhd::rfnoc::SR_READBACK,
+                uhd::rfnoc::SR_READBACK_REG_ID,
+                true
         );
-        uint64_t noc_id = ctrl->send_cmd_pkt(uhd::rfnoc::SR_READBACK, uhd::rfnoc::SR_READBACK_REG_ID, true);
-        UHD_DEVICE3_LOG() << str(boost::format("Port %d: Found NoC-Block with ID %016X.") % int(ctrl_sid.get_dst_endpoint()) % noc_id) ;
+        UHD_LOG_DEBUG("DEVICE3", str(
+            boost::format("Port 0x%02X: Found NoC-Block with ID %016X.")
+                % int(ctrl_sid.get_dst_endpoint())
+                % noc_id
+        ));
         uhd::rfnoc::make_args_t make_args;
         uhd::rfnoc::blockdef::sptr block_def = uhd::rfnoc::blockdef::make_from_noc_id(noc_id);
         if (not block_def) {
-            UHD_DEVICE3_LOG() << "Using default block configuration." ;
-            block_def = uhd::rfnoc::blockdef::make_from_noc_id(uhd::rfnoc::DEFAULT_NOC_ID);
+            UHD_LOG_WARNING("DEVICE3",
+                "No block definition found, using default block configuration "
+                "for block with NOC ID: " + str(boost::format("0x%08X") % noc_id)
+            );
+            block_def = uhd::rfnoc::blockdef::make_from_noc_id(
+                uhd::rfnoc::DEFAULT_NOC_ID);
         }
         UHD_ASSERT_THROW(block_def);
         make_args.ctrl_ifaces[0] = ctrl;
-        for(const size_t port_number:  block_def->get_all_port_numbers()) {
+        for (const size_t port_number : block_def->get_all_port_numbers()) {
             if (port_number == 0) { // We've already set this up
                 continue;
             }
@@ -142,14 +156,22 @@ void device3_impl::enumerate_rfnoc_blocks(
                 CTRL,
                 transport_args
             );
-            UHD_DEVICE3_LOG() << str(boost::format("Setting up NoC-Shell Control for port #%d (SID: %s)...") % port_number % xport1.send_sid.to_pp_string_hex());
+            UHD_LOG_TRACE("DEVICE3", str(
+                    boost::format("Setting up NoC-Shell Control for port #%d "
+                                  "(SID: %s)...")
+                    % port_number
+                    % xport1.send_sid.to_pp_string_hex()
+            ));
             uhd::rfnoc::ctrl_iface::sptr ctrl1 = uhd::rfnoc::ctrl_iface::make(
                     xport1,
                     str(boost::format("CE_%02d_Port_%02d") % i % ctrl_sid.get_dst_endpoint())
             );
-            UHD_DEVICE3_LOG() << "OK" ;
             make_args.ctrl_ifaces[port_number] = ctrl1;
         }
+        UHD_LOG_TRACE("DEVICE3",
+            "All control transports successfully created for block with ID " <<
+            str(boost::format("0x%08X") % noc_id)
+        );
 
         make_args.base_address = xport.send_sid.get_dst();
         make_args.device_index = device_index;