uhd: Fixed logging bug (#476) -- UHD logging has unexplained effect on packet loss.

- Removed logging from radio_ctrl_core_3000
- Changed logging facility to prevent type conversion when message is not logged

3 files changed, 53 insertions, 43 deletions

diff --git a/host/include/uhd/utils/log.hpp b/host/include/uhd/utils/log.hpp
index 1f515c15e..5baa00108 100644
--- a/host/include/uhd/utils/log.hpp
+++ b/host/include/uhd/utils/log.hpp
@@ -21,8 +21,10 @@
 #include <uhd/config.hpp>
 #include <uhd/utils/pimpl.hpp>
 #include <boost/current_function.hpp>
+#include <boost/format.hpp>
 #include <ostream>
 #include <string>
+#include <sstream>
 
 /*! \file log.hpp
  * The UHD logging facility.
@@ -55,7 +57,7 @@
  * Usage: UHD_LOGV(very_rarely) << "the log message" << std::endl;
  */
 #define UHD_LOGV(verbosity) \
-    uhd::_log::log(uhd::_log::verbosity, __FILE__, __LINE__, BOOST_CURRENT_FUNCTION)()
+    uhd::_log::log(uhd::_log::verbosity, __FILE__, __LINE__, BOOST_CURRENT_FUNCTION)
 
 /*!
  * A UHD logger macro with default verbosity.
@@ -78,7 +80,7 @@ namespace uhd{ namespace _log{
     };
 
     //! Internal logging object (called by UHD_LOG macros)
-    class UHD_API log{
+    class UHD_API log {
     public:
         log(
             const verbosity_t verbosity,
@@ -86,10 +88,29 @@ namespace uhd{ namespace _log{
             const unsigned int line,
             const std::string &function
         );
+
         ~log(void);
-        std::ostream &operator()(void);
+
+        // Macro for overloading insertion operators to avoid costly
+        // conversion of types if not logging.
+        #define INSERTION_OVERLOAD(x)   log& operator<< (x)             \
+                                        {                               \
+                                            if(_log_it) _ss << val;     \
+                                            return *this;               \
+                                        }
+
+        // General insertion overload
+        template <typename T>
+        INSERTION_OVERLOAD(T val);
+
+        // Insertion overloads for std::ostream manipulators
+        INSERTION_OVERLOAD(std::ostream& (*val)(std::ostream&));
+        INSERTION_OVERLOAD(std::ios& (*val)(std::ios&));
+        INSERTION_OVERLOAD(std::ios_base& (*val)(std::ios_base&));
+
     private:
-        UHD_PIMPL_DECL(impl) _impl;
+        std::ostringstream _ss;
+        bool _log_it;
     };
 
 }} //namespace uhd::_log
diff --git a/host/lib/usrp/cores/radio_ctrl_core_3000.cpp b/host/lib/usrp/cores/radio_ctrl_core_3000.cpp
index 2005bcf33..15af1888b 100644
--- a/host/lib/usrp/cores/radio_ctrl_core_3000.cpp
+++ b/host/lib/usrp/cores/radio_ctrl_core_3000.cpp
@@ -52,7 +52,6 @@ public:
                     ACK_TIMEOUT), _resp_queue(128/*max response msgs*/), _resp_queue_size(
                     _resp_xport ? _resp_xport->get_num_recv_frames() : 3)
     {
-        UHD_LOG<< "radio_ctrl_core_3000_impl() " << _name << std::endl;
         if (resp_xport)
         {
             while (resp_xport->get_recv_buff(0.0)) {} //flush
@@ -63,7 +62,6 @@ public:
 
     ~radio_ctrl_core_3000_impl(void)
     {
-        UHD_LOG << "~radio_ctrl_core_3000_impl() " << _name << std::endl;
         _timeout = ACK_TIMEOUT; //reset timeout to something small
         UHD_SAFE_CALL(
             this->peek32(0);//dummy peek with the purpose of ack'ing all packets
@@ -77,8 +75,6 @@ public:
     void poke32(const wb_addr_type addr, const boost::uint32_t data)
     {
         boost::mutex::scoped_lock lock(_mutex);
-        UHD_LOGV(always) << _name << std::hex << " addr 0x" << addr << " data 0x" << data << std::dec << std::endl;
-
         this->send_pkt(addr/4, data);
         this->wait_for_ack(false);
     }
@@ -86,7 +82,6 @@ public:
     boost::uint32_t peek32(const wb_addr_type addr)
     {
         boost::mutex::scoped_lock lock(_mutex);
-        UHD_LOGV(always) << _name << std::hex << " addr 0x" << addr << std::dec << std::endl;
         this->send_pkt(SR_READBACK, addr/8);
         const boost::uint64_t res = this->wait_for_ack(true);
         const boost::uint32_t lo = boost::uint32_t(res & 0xffffffff);
@@ -97,8 +92,6 @@ public:
     boost::uint64_t peek64(const wb_addr_type addr)
     {
         boost::mutex::scoped_lock lock(_mutex);
-        UHD_LOGV(always) << _name << std::hex << " addr 0x" << addr << std::dec << std::endl;
-
         this->send_pkt(SR_READBACK, addr/8);
         return this->wait_for_ack(true);
     }
@@ -174,7 +167,6 @@ private:
     {
         while (readback or (_outstanding_seqs.size() >= _resp_queue_size))
         {
-            UHD_LOGV(always) << _name << " wait_for_ack: " << "readback = " << readback << " outstanding_seqs.size() " << _outstanding_seqs.size() << std::endl;
             //get seq to ack from outstanding packets list
             UHD_ASSERT_THROW(not _outstanding_seqs.empty());
             const size_t seq_to_ack = _outstanding_seqs.front();
diff --git a/host/lib/utils/log.cpp b/host/lib/utils/log.cpp
index 31ee0c991..123b7e4e6 100644
--- a/host/lib/utils/log.cpp
+++ b/host/lib/utils/log.cpp
@@ -23,6 +23,7 @@
 #include <boost/format.hpp>
 #include <boost/thread/mutex.hpp>
 #include <boost/date_time/posix_time/posix_time.hpp>
+#include <boost/thread/lock_guard.hpp>
 #ifdef BOOST_MSVC
 //whoops! https://svn.boost.org/trac/boost/ticket/5287
 //enjoy this useless dummy class instead
@@ -37,7 +38,6 @@ namespace boost{ namespace interprocess{
 #include <boost/interprocess/sync/file_lock.hpp>
 #endif
 #include <fstream>
-#include <sstream>
 #include <cctype>
 
 namespace fs = boost::filesystem;
@@ -70,13 +70,13 @@ public:
     }
 
     ~log_resource_type(void){
-        boost::mutex::scoped_lock lock(_mutex);
+        boost::lock_guard<boost::mutex> lock(_mutex);
         _file_stream.close();
         if (_file_lock != NULL) delete _file_lock;
     }
 
     void log_to_file(const std::string &log_msg){
-        boost::mutex::scoped_lock lock(_mutex);
+        boost::lock_guard<boost::mutex> lock(_mutex);
         if (_file_lock == NULL){
             const std::string log_path = (fs::path(uhd::get_tmp_path()) / "uhd.log").string();
             _file_stream.open(log_path.c_str(), std::fstream::out | std::fstream::app);
@@ -126,39 +126,40 @@ static std::string get_rel_file_path(const fs::path &file){
     return rel_path.string();
 }
 
-struct uhd::_log::log::impl{
-    std::ostringstream ss;
-    verbosity_t verbosity;
-};
 
 uhd::_log::log::log(
     const verbosity_t verbosity,
     const std::string &file,
     const unsigned int line,
     const std::string &function
-){
-    _impl = UHD_PIMPL_MAKE(impl, ());
-    _impl->verbosity = verbosity;
-    const std::string time = pt::to_simple_string(pt::microsec_clock::local_time());
-    const std::string header1 = str(boost::format("-- %s - level %d") % time % int(verbosity));
-    const std::string header2 = str(boost::format("-- %s") % function).substr(0, 80);
-    const std::string header3 = str(boost::format("-- %s:%u") % get_rel_file_path(file) % line);
-    const std::string border = std::string(std::max(std::max(header1.size(), header2.size()), header3.size()), '-');
-    _impl->ss
-        << std::endl
-        << border << std::endl
-        << header1 << std::endl
-        << header2 << std::endl
-        << header3 << std::endl
-        << border << std::endl
-    ;
+    )
+{
+    _log_it = (verbosity >= log_rs().level);
+    if (_log_it)
+    {
+        const std::string time = pt::to_simple_string(pt::microsec_clock::local_time());
+        const std::string header1 = str(boost::format("-- %s - level %d") % time % int(verbosity));
+        const std::string header2 = str(boost::format("-- %s") % function).substr(0, 80);
+        const std::string header3 = str(boost::format("-- %s:%u") % get_rel_file_path(file) % line);
+        const std::string border = std::string(std::max(std::max(header1.size(), header2.size()), header3.size()), '-');
+        _ss << std::endl
+            << border << std::endl
+            << header1 << std::endl
+            << header2 << std::endl
+            << header3 << std::endl
+            << border << std::endl
+        ;
+    }
 }
 
-uhd::_log::log::~log(void){
-    if (_impl->verbosity < log_rs().level) return;
-    _impl->ss << std::endl;
+uhd::_log::log::~log(void)
+{
+    if (not _log_it)
+        return;
+
+    _ss << std::endl;
     try{
-        log_rs().log_to_file(_impl->ss.str());
+        log_rs().log_to_file(_ss.str());
     }
     catch(const std::exception &e){
         /*!
@@ -174,7 +175,3 @@ uhd::_log::log::~log(void){
         ;
     }
 }
-
-std::ostream & uhd::_log::log::operator()(void){
-    return _impl->ss;
-}