Add some diagnostics to PSKReporter class

Sent to the severity channel log source PSKRPRT.
This commit is contained in:
Bill Somerville 2021-01-26 14:36:13 +00:00
parent 9048c5cf04
commit 29a113b73a
No known key found for this signature in database
GPG Key ID: D864B06D1E81618F
3 changed files with 40 additions and 11 deletions

View File

@ -184,13 +184,13 @@ void SoundInput::reset (bool report_dropped_frames)
{ {
LOG_WARN ("Detected dropped audio source samples: " LOG_WARN ("Detected dropped audio source samples: "
<< m_stream->format ().framesForDuration (lost_usec) << 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) else if (std::abs (lost_usec) > 5 * 48000)
{ {
LOG_ERROR ("Detected excessive dropped audio source samples: " LOG_ERROR ("Detected excessive dropped audio source samples: "
<< m_stream->format ().framesForDuration (lost_usec) << 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 (); cummulative_lost_usec_ = elapsed_usecs - m_stream->processedUSecs ();

View File

@ -35,16 +35,16 @@ namespace Logger
BOOST_LOG_SEV (LOGGER, boost::log::trivial::LEVEL) \ BOOST_LOG_SEV (LOGGER, boost::log::trivial::LEVEL) \
<< boost::log::add_value ("Line", __LINE__) \ << boost::log::add_value ("Line", __LINE__) \
<< boost::log::add_value ("File", __FILE__) \ << boost::log::add_value ("File", __FILE__) \
<< boost::log::add_value ("Function", __FUNCTION__) << ARG; << boost::log::add_value ("Function", __FUNCTION__) << ARG
/// System Log macros. /// System Log macros.
/// TRACE < DEBUG < INFO < WARN < ERROR < FATAL /// 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. /// Data Log macros. Does not include LINE, FILE, FUNCTION.
/// TRACE < DEBUG < INFO < WARN < ERROR < FATAL /// TRACE < DEBUG < INFO < WARN < ERROR < FATAL

View File

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