Add some diagnostics to PSKReporter class

Sent to the severity channel log source PSKRPRT.

Audio/soundin.cpp

@@ -184,13 +184,13 @@ void SoundInput::reset (bool report_dropped_frames)
             {
               LOG_WARN ("Detected dropped audio source samples: "
                         << m_stream->format ().framesForDuration (lost_usec)
-                        << " (" << std::setprecision (4) << lost_usec / 1.e6 << " S)")
+                        << " (" << std::setprecision (4) << lost_usec / 1.e6 << " S)");
             }
           else if (std::abs (lost_usec) > 5 * 48000)
             {
               LOG_ERROR ("Detected excessive dropped audio source samples: "
                         << m_stream->format ().framesForDuration (lost_usec)
-                        << " (" << std::setprecision (4) << lost_usec / 1.e6 << " S)")
+                         << " (" << std::setprecision (4) << lost_usec / 1.e6 << " S)");
             }
         }
       cummulative_lost_usec_ = elapsed_usecs - m_stream->processedUSecs ();

Logger.hpp

@@ -35,16 +35,16 @@ namespace Logger
   BOOST_LOG_SEV (LOGGER, boost::log::trivial::LEVEL)          \
   << boost::log::add_value ("Line", __LINE__)                 \
   << boost::log::add_value ("File", __FILE__)                 \
-  << boost::log::add_value ("Function", __FUNCTION__) << ARG;
+  << boost::log::add_value ("Function", __FUNCTION__) << ARG
  
 /// System Log macros.
 /// TRACE < DEBUG < INFO < WARN < ERROR < FATAL
-#define LOG_TRACE(ARG) LOG_LOG_LOCATION (sys::get(), trace, ARG);
+#define LOG_TRACE(ARG) LOG_LOG_LOCATION (sys::get(), trace, ARG)
-#define LOG_DEBUG(ARG) LOG_LOG_LOCATION (sys::get(), debug, ARG);
+#define LOG_DEBUG(ARG) LOG_LOG_LOCATION (sys::get(), debug, ARG)
-#define LOG_INFO(ARG)  LOG_LOG_LOCATION (sys::get(), info, ARG);
+#define LOG_INFO(ARG)  LOG_LOG_LOCATION (sys::get(), info, ARG)
-#define LOG_WARN(ARG)  LOG_LOG_LOCATION (sys::get(), warning, ARG);
+#define LOG_WARN(ARG)  LOG_LOG_LOCATION (sys::get(), warning, ARG)
-#define LOG_ERROR(ARG) LOG_LOG_LOCATION (sys::get(), error, ARG);
+#define LOG_ERROR(ARG) LOG_LOG_LOCATION (sys::get(), error, ARG)
-#define LOG_FATAL(ARG) LOG_LOG_LOCATION (sys::get(), fatal, ARG);
+#define LOG_FATAL(ARG) LOG_LOG_LOCATION (sys::get(), fatal, ARG)
  
 /// Data Log macros. Does not include LINE, FILE, FUNCTION.
 /// TRACE < DEBUG < INFO < WARN < ERROR < FATAL

Network/PSKReporter.cpp

@@ -22,6 +22,7 @@
 #include <QRandomGenerator>
 #endif
 
+#include "Logger.hpp"
 #include "Configuration.hpp"
 #include "pimpl_impl.hpp"
 
@@ -46,9 +47,12 @@ class PSKReporter::impl final
 {
   Q_OBJECT
 
+  using logger_type = boost::log::sources::severity_channel_logger_mt<boost::log::trivial::severity_level>;
+
 public:
   impl (PSKReporter * self, Configuration const * config, QString const& program_info)
-    : self_ {self}
+    : logger_ {boost::log::keywords::channel = "PSKRPRT"}
+    , self_ {self}
     , config_ {config}
     , sequence_number_ {0u}
     , send_descriptors_ {0}
@@ -72,6 +76,7 @@ public:
                                                      if (socket_
                                                          && QAbstractSocket::UdpSocket == socket_->socketType ())
                                                        {
+                                                         LOG_LOG_LOCATION (logger_, trace, "enable descriptor resend");
                                                          // send templates again
                                                          send_descriptors_ = 3; // three times
                                                          // send receiver data set again
@@ -91,6 +96,7 @@ public:
             && QAbstractSocket::UnconnectedState != socket_->state ()
             && QAbstractSocket::ClosingState != socket_->state ())
           {
+            LOG_LOG_LOCATION (logger_, trace, "create/recreate socket");
             // handle re-opening asynchronously
             auto connection = QSharedPointer<QMetaObject::Connection>::create ();
             *connection = connect (socket_.data (), &QAbstractSocket::disconnected, [this, connection] () {
@@ -110,6 +116,7 @@ public:
 
   void handle_socket_error (QAbstractSocket::SocketError e)
   {
+    LOG_LOG_LOCATION (logger_, trace, "err: " << e);
     switch (e)
       {
       case QAbstractSocket::RemoteHostClosedError:
@@ -132,12 +139,14 @@ public:
     // be called from the disconnected handler above.
     if (config_->psk_reporter_tcpip ())
       {
+        LOG_LOG_LOCATION (logger_, trace, "create TCP/IP socket");
         socket_.reset (new QTcpSocket, &QObject::deleteLater);
         send_descriptors_ = 1;
         send_receiver_data_ = 1;
       }
     else
       {
+        LOG_LOG_LOCATION (logger_, trace, "create UDP/IP socket");
         socket_.reset (new QUdpSocket, &QObject::deleteLater);
         send_descriptors_ = 3;
         send_receiver_data_ = 3;
@@ -154,6 +163,7 @@ public:
     // use this for pseudo connection with UDP, allows us to use
     // QIODevice::write() instead of QUDPSocket::writeDatagram()
     socket_->connectToHost (HOST, SERVICE_PORT, QAbstractSocket::WriteOnly);
+    LOG_LOG_LOCATION (logger_, debug, "remote host: " << HOST << " port: " << SERVICE_PORT);
 
     if (!report_timer_.isActive ())
       {
@@ -169,6 +179,7 @@ public:
   {
     if (socket_)
       {
+        LOG_LOG_LOCATION (logger_, trace, "disconnecting");
         socket_->disconnectFromHost ();
       }
     descriptor_timer_.stop ();
@@ -180,9 +191,12 @@ public:
 
   bool flushing ()
   {
-    return FLUSH_INTERVAL && !(++flush_counter_ % FLUSH_INTERVAL);
+    bool flush =  FLUSH_INTERVAL && !(++flush_counter_ % FLUSH_INTERVAL);
+    LOG_LOG_LOCATION (logger_, trace, "flush: " << flush);
+    return flush;
   }
 
+  logger_type mutable logger_;
   PSKReporter * self_;
   Configuration const * config_;
   QSharedPointer<QAbstractSocket> socket_;
@@ -267,6 +281,7 @@ void PSKReporter::impl::build_preamble (QDataStream& message)
     << quint32 (0u)           // Export Time (place-holder filled in later)
     << ++sequence_number_     // Sequence Number
     << observation_id_;       // Observation Domain ID
+  LOG_LOG_LOCATION (logger_, trace, "#: " << sequence_number_);
 
   if (send_descriptors_)
     {
@@ -329,6 +344,7 @@ void PSKReporter::impl::build_preamble (QDataStream& message)
         // insert Length
         set_length (out, descriptor);
         message.writeRawData (descriptor.constData (), descriptor.size ());
+        LOG_LOG_LOCATION (logger_, debug, "sent descriptors");
       }
     }
 
@@ -354,11 +370,13 @@ void PSKReporter::impl::build_preamble (QDataStream& message)
     // insert Length and move to payload
     set_length (out, data);
     message.writeRawData (data.constData (), data.size ());
+    LOG_LOG_LOCATION (logger_, debug, "sent local information");
   }
 }
 
 void PSKReporter::impl::send_report (bool send_residue)
 {
+  LOG_LOG_LOCATION (logger_, trace, "sending residue: " << send_residue);
   if (QAbstractSocket::ConnectedState != socket_->state ()) return;
 
   QDataStream message {&payload_, QIODevice::WriteOnly | QIODevice::Append};
@@ -391,9 +409,11 @@ void PSKReporter::impl::send_report (bool send_residue)
       if (tx_residue_.size ())
         {
           tx_out.writeRawData (tx_residue_.constData (), tx_residue_.size ());
+          LOG_LOG_LOCATION (logger_, debug, "sent residue");
           tx_residue_.clear ();
         }
 
+      LOG_LOG_LOCATION (logger_, debug, "pending spots: " << spots_.size ());
       while (spots_.size () || flush)
         {
           auto tx_data_size = tx_data_.size ();
@@ -452,6 +472,7 @@ void PSKReporter::impl::send_report (bool send_residue)
 
               // Send data to PSK Reporter site
               socket_->write (payload_); // TODO: handle errors
+              LOG_LOG_LOCATION (logger_, debug, "sent spots");
               flush = false;    // break loop
               message.device ()->seek (0u);
               payload_.clear ();  // Fresh message
@@ -462,29 +483,35 @@ void PSKReporter::impl::send_report (bool send_residue)
               break;
             }
         }
+      LOG_LOG_LOCATION (logger_, debug, "remaining spots: " << spots_.size ());
     }
 }
 
 PSKReporter::PSKReporter (Configuration const * config, QString const& program_info)
   : m_ {this, config, program_info}
 {
+  LOG_LOG_LOCATION (m_->logger_, trace, "Started for: " << program_info);
 }
 
 PSKReporter::~PSKReporter ()
 {
   // m_->send_report (true);       // send any pending spots
+  LOG_LOG_LOCATION (m_->logger_, trace, "Ended");
 }
 
 void PSKReporter::reconnect ()
 {
+  LOG_LOG_LOCATION (m_->logger_, trace, "");
   m_->reconnect ();
 }
 
 void PSKReporter::setLocalStation (QString const& call, QString const& gridSquare, QString const& antenna)
 {
+  LOG_LOG_LOCATION (m_->logger_, trace, "call: " << call << " grid: " << gridSquare << " ant: " << antenna);
   m_->check_connection ();
   if (call != m_->rx_call_ || gridSquare != m_->rx_grid_ || antenna != m_->rx_ant_)
     {
+      LOG_LOG_LOCATION (m_->logger_, trace, "updating information");
       m_->send_receiver_data_ = m_->socket_
         && QAbstractSocket::UdpSocket == m_->socket_->socketType () ? 3 : 1;
       m_->rx_call_ = call;
@@ -496,6 +523,7 @@ void PSKReporter::setLocalStation (QString const& call, QString const& gridSquar
 bool PSKReporter::addRemoteStation (QString const& call, QString const& grid, Radio::Frequency freq
                                      , QString const& mode, int snr)
 {
+  LOG_LOG_LOCATION (m_->logger_, trace, "call: " << call << " grid: " << grid << " freq: " << freq << " mode: " << mode << " snr: " << snr);
   m_->check_connection ();
   if (m_->socket_ && m_->socket_->isValid ())
     {
@@ -511,6 +539,7 @@ bool PSKReporter::addRemoteStation (QString const& call, QString const& grid, Ra
 
 void PSKReporter::sendReport (bool last)
 {
+  LOG_LOG_LOCATION (m_->logger_, trace, "last: " << last);
   m_->check_connection ();
   if (m_->socket_ && QAbstractSocket::ConnectedState == m_->socket_->state ())
     {