From 04ef69984136a2260006fe98614ed6362b0df3ad Mon Sep 17 00:00:00 2001
From: Bill Somerville <bill@classdesign.com>
Date: Tue, 26 Jan 2021 14:36:13 +0000
Subject: [PATCH] Add some diagnostics to PSKReporter class
Sent to the severity channel log source PSKRPRT.
---
Audio/soundin.cpp | 4 ++--
Logger.hpp | 14 +++++++-------
Network/PSKReporter.cpp | 33 +++++++++++++++++++++++++++++++--
3 files changed, 40 insertions(+), 11 deletions(-)
diff --git a/Audio/soundin.cpp b/Audio/soundin.cpp
index 53a29799c..d9bc78446 100644
--- a/Audio/soundin.cpp
+++ b/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 ();
diff --git a/Logger.hpp b/Logger.hpp
index 5d497943f..0eed8aae2 100644
--- a/Logger.hpp
+++ b/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_DEBUG(ARG) LOG_LOG_LOCATION (sys::get(), debug, 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_ERROR(ARG) LOG_LOG_LOCATION (sys::get(), error, ARG);
-#define LOG_FATAL(ARG) LOG_LOG_LOCATION (sys::get(), fatal, 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_INFO(ARG) LOG_LOG_LOCATION (sys::get(), info, 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_FATAL(ARG) LOG_LOG_LOCATION (sys::get(), fatal, ARG)
/// Data Log macros. Does not include LINE, FILE, FUNCTION.
/// TRACE < DEBUG < INFO < WARN < ERROR < FATAL
diff --git a/Network/PSKReporter.cpp b/Network/PSKReporter.cpp
index 35c56f23f..c072860f8 100644
--- a/Network/PSKReporter.cpp
+++ b/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 ())
{