Refactored logging enhancements

logging.h/logging.cpp is now a full-fledged pair for all things logging. Two more categories added, EPHEMERAL and SYNCJOB, that control logging for ephemeral events and SyncJob, respectively (in particular, switching off EPHEMERAL greatly reduces the logspam about moving read markers and how many users have read up to which event).

3 files changed, 36 insertions, 18 deletions

diff --git a/jobs/basejob.cpp b/jobs/basejob.cpp
index f5de75f4..77f90596 100644
--- a/jobs/basejob.cpp
+++ b/jobs/basejob.cpp
@@ -17,16 +17,15 @@
  */
 
 #include "basejob.h"
-#include "util.h"
 
-#include <array>
+#include "connectiondata.h"
 
 #include <QtNetwork/QNetworkAccessManager>
 #include <QtNetwork/QNetworkRequest>
 #include <QtNetwork/QNetworkReply>
 #include <QtCore/QTimer>
 
-#include "../connectiondata.h"
+#include <array>
 
 using namespace QMatrixClient;
 
@@ -49,10 +48,10 @@ class BaseJob::Private
                 QString endpoint, QUrlQuery q, Data data, bool nt)
             : connection(c), verb(v), apiEndpoint(std::move(endpoint))
             , requestQuery(std::move(q)), requestData(std::move(data))
-            , needsToken(nt), reply(nullptr), status(NoError)
+            , needsToken(nt)
         { }
         
-        inline void sendRequest();
+        void sendRequest();
 
         const ConnectionData* connection;
 
@@ -64,13 +63,15 @@ class BaseJob::Private
         bool needsToken;
 
         QScopedPointer<QNetworkReply, NetworkReplyDeleter> reply;
-        Status status;
+        Status status = NoError;
 
         QTimer timer;
         QTimer retryTimer;
 
         size_t maxRetries = 3;
         size_t retriesTaken = 0;
+
+        LoggingCategory logCat = JOBS;
 };
 
 inline QDebug operator<<(QDebug dbg, const BaseJob* j)
@@ -88,13 +89,13 @@ BaseJob::BaseJob(const ConnectionData* connection, HttpVerb verb,
     connect (&d->timer, &QTimer::timeout, this, &BaseJob::timeout);
     d->retryTimer.setSingleShot(true);
     connect (&d->retryTimer, &QTimer::timeout, this, &BaseJob::start);
-    qCDebug(JOBS) << this << "created";
+    qCDebug(d->logCat) << this << "created";
 }
 
 BaseJob::~BaseJob()
 {
     stop();
-    qCDebug(JOBS) << this << "destroyed";
+    qCDebug(d->logCat) << this << "destroyed";
 }
 
 const ConnectionData* BaseJob::connection() const
@@ -176,7 +177,7 @@ void BaseJob::gotReply()
 BaseJob::Status BaseJob::checkReply(QNetworkReply* reply) const
 {
     if (reply->error() != QNetworkReply::NoError)
-        qCDebug(JOBS) << this << "returned" << reply->error();
+        qCDebug(d->logCat) << this << "returned" << reply->error();
     switch( reply->error() )
     {
     case QNetworkReply::NoError:
@@ -219,11 +220,11 @@ void BaseJob::stop()
     d->timer.stop();
     if (!d->reply)
     {
-        qCWarning(JOBS) << this << "stopped with empty network reply";
+        qCWarning(d->logCat) << this << "stopped with empty network reply";
     }
     else if (d->reply->isRunning())
     {
-        qCWarning(JOBS) << this << "stopped without ready network reply";
+        qCWarning(d->logCat) << this << "stopped without ready network reply";
         d->reply->disconnect(this); // Ignore whatever comes from the reply
         d->reply->abort();
     }
@@ -237,7 +238,7 @@ void BaseJob::finishJob()
     {
         const auto retryInterval = getNextRetryInterval();
         ++d->retriesTaken;
-        qCWarning(JOBS) << this << "will take retry" << d->retriesTaken
+        qCWarning(d->logCat) << this << "will take retry" << d->retriesTaken
                    << "in" << retryInterval/1000 << "s";
         d->retryTimer.start(retryInterval);
         emit retryScheduled(d->retriesTaken, retryInterval);
@@ -303,7 +304,8 @@ void BaseJob::setStatus(Status s)
     d->status = s;
     if (!s.good())
     {
-        qCWarning(JOBS) << this << "status" << s.code << ":" << s.message;
+        qCWarning(d->logCat) << this << "status" << s.code
+                                     << ":" << s.message;
     }
 }
 
@@ -326,7 +328,13 @@ void BaseJob::timeout()
 void BaseJob::sslErrors(const QList<QSslError>& errors)
 {
     foreach (const QSslError &error, errors) {
-        qCWarning(JOBS) << "SSL ERROR" << error.errorString();
+        qCWarning(d->logCat) << "SSL ERROR" << error.errorString();
     }
     d->reply->ignoreSslErrors(); // TODO: insecure! should prompt user first
 }
+
+void BaseJob::setLoggingCategory(LoggingCategory lcf)
+{
+    d->logCat = lcf;
+}
+
diff --git a/jobs/basejob.h b/jobs/basejob.h
index 460af0fc..2be4577f 100644
--- a/jobs/basejob.h
+++ b/jobs/basejob.h
@@ -18,6 +18,8 @@
 
 #pragma once
 
+#include "logging.h"
+
 #include <QtCore/QObject>
 #include <QtCore/QJsonDocument>
 #include <QtCore/QJsonObject>
@@ -241,6 +243,11 @@ namespace QMatrixClient
             void setStatus(Status s);
             void setStatus(int code, QString message);
 
+            // Q_DECLARE_LOGGING_CATEGORY return different function types
+            // in different versions
+            using LoggingCategory = decltype(JOBS)*;
+            void setLoggingCategory(LoggingCategory lcf);
+
             // Job objects should only be deleted via QObject::deleteLater
             virtual ~BaseJob();
         protected slots:
@@ -257,4 +264,4 @@ namespace QMatrixClient
             class Private;
             QScopedPointer<Private> d;
     };
-}
+}  // namespace QMatrixClient
diff --git a/jobs/syncjob.cpp b/jobs/syncjob.cpp
index 17c637b0..fb6bb9b9 100644
--- a/jobs/syncjob.cpp
+++ b/jobs/syncjob.cpp
@@ -19,7 +19,7 @@
 #include "syncjob.h"
 
 #include <QtCore/QJsonArray>
-#include <QtCore/QDebug>
+#include <QtCore/QElapsedTimer>
 
 using namespace QMatrixClient;
 
@@ -38,6 +38,7 @@ SyncJob::SyncJob(const ConnectionData* connection, const QString& since,
               "_matrix/client/r0/sync")
     , d(new Private)
 {
+    setLoggingCategory(SYNCJOB);
     QUrlQuery query;
     if( !filter.isEmpty() )
         query.addQueryItem("filter", filter);
@@ -69,6 +70,7 @@ SyncData& SyncJob::roomData()
 
 BaseJob::Status SyncJob::parseJson(const QJsonDocument& data)
 {
+    QElapsedTimer et; et.start();
     QJsonObject json = data.object();
     d->nextBatch = json.value("next_batch").toString();
     // TODO: presence
@@ -89,6 +91,7 @@ BaseJob::Status SyncJob::parseJson(const QJsonDocument& data)
         for( auto rkey: rs.keys() )
             d->roomData.emplace_back(rkey, roomState.enumVal, rs[rkey].toObject());
     }
+    qCDebug(PROFILER) << "*** SyncJob::parseJson():" << et.elapsed() << "ms";
 
     return Success;
 }
@@ -123,7 +126,7 @@ SyncRoomData::SyncRoomData(const QString& roomId_, JoinState joinState_,
             timeline.fromJson(room_);
             break;
     default:
-        qCWarning(JOBS) << "SyncRoomData: Unknown JoinState value, ignoring:" << int(joinState);
+        qCWarning(SYNCJOB) << "SyncRoomData: Unknown JoinState value, ignoring:" << int(joinState);
     }
 
     QJsonObject timeline = room_.value("timeline").toObject();
@@ -133,5 +136,5 @@ SyncRoomData::SyncRoomData(const QString& roomId_, JoinState joinState_,
     QJsonObject unread = room_.value("unread_notifications").toObject();
     highlightCount = unread.value("highlight_count").toInt();
     notificationCount = unread.value("notification_count").toInt();
-    qCDebug(JOBS) << "Highlights: " << highlightCount << " Notifications:" << notificationCount;
+    qCDebug(SYNCJOB) << "Highlights: " << highlightCount << " Notifications:" << notificationCount;
 }