Introduced debug areas and prettified output.

13 files changed, 82 insertions, 31 deletions

diff --git a/common/clientapi.cpp b/common/clientapi.cpp
index be9f3fd..a13456b 100644
--- a/common/clientapi.cpp
+++ b/common/clientapi.cpp
@@ -39,6 +39,9 @@
 #include "storage.h"
 #include "log.h"
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "client.clientapi"
+
 namespace Sink
 {
 
diff --git a/common/facade.cpp b/common/facade.cpp
index 8cb776c..95fecd9 100644
--- a/common/facade.cpp
+++ b/common/facade.cpp
@@ -29,6 +29,9 @@
 
 using namespace Sink;
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "client.facade"
+
 class ResourceAccessFactory {
 public:
     static ResourceAccessFactory &instance()
diff --git a/common/genericresource.cpp b/common/genericresource.cpp
index 29cd8b1..b49ca94 100644
--- a/common/genericresource.cpp
+++ b/common/genericresource.cpp
@@ -22,6 +22,9 @@ static int sBatchSize = 100;
 
 using namespace Sink;
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "resource.changereplay"
+
 /**
  * Replays changes from the storage one by one.
  *
@@ -110,6 +113,9 @@ private:
     ReplayFunction mReplayFunction;
 };
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "resource.commandprocessor"
+
 /**
  * Drives the pipeline using the output from all command queues
  */
@@ -286,6 +292,8 @@ private:
     InspectionFunction mInspect;
 };
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "resource"
 
 GenericResource::GenericResource(const QByteArray &resourceInstanceIdentifier, const QSharedPointer<Pipeline> &pipeline)
     : Sink::Resource(),
@@ -312,7 +320,7 @@ GenericResource::GenericResource(const QByteArray &resourceInstanceIdentifier, c
             QVariant expectedValue;
             s >> expectedValue;
             inspect(inspectionType, inspectionId, domainType, entityId, property, expectedValue).then<void>([=]() {
-                Log() << "Inspection was successful: " << inspectionType << inspectionId << entityId;
+                Log_area("resource.inspection") << "Inspection was successful: " << inspectionType << inspectionId << entityId;
                 Sink::Notification n;
                 n.type = Sink::Commands::NotificationType_Inspection;
                 n.id = inspectionId;
@@ -384,7 +392,6 @@ KAsync::Job<void> GenericResource::replay(Sink::Storage &synchronizationStore, c
 
 void GenericResource::removeFromDisk(const QByteArray &instanceIdentifier)
 {
-    Warning() << "Removing from generic resource";
     Sink::Storage(Sink::storageLocation(), instanceIdentifier, Sink::Storage::ReadWrite).removeFromDisk();
     Sink::Storage(Sink::storageLocation(), instanceIdentifier + ".userqueue", Sink::Storage::ReadWrite).removeFromDisk();
     Sink::Storage(Sink::storageLocation(), instanceIdentifier + ".synchronizerqueue", Sink::Storage::ReadWrite).removeFromDisk();
diff --git a/common/listener.cpp b/common/listener.cpp
index 6b62552..323252b 100644
--- a/common/listener.cpp
+++ b/common/listener.cpp
@@ -39,6 +39,9 @@
 #include <QTime>
 #include <QDataStream>
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "resource.communication"
+
 Listener::Listener(const QByteArray &resourceInstanceIdentifier, QObject *parent)
     : QObject(parent),
       m_server(new QLocalServer(this)),
diff --git a/common/modelresult.cpp b/common/modelresult.cpp
index 3a9fb95..f28c665 100644
--- a/common/modelresult.cpp
+++ b/common/modelresult.cpp
@@ -24,6 +24,9 @@
 #include "domain/folder.h"
 #include "log.h"
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "client.modelresult"
+
 static  uint qHash(const Sink::ApplicationDomain::ApplicationDomainType &type)
 {
     Q_ASSERT(!type.resourceInstanceIdentifier().isEmpty());
diff --git a/common/pipeline.cpp b/common/pipeline.cpp
index db79dc8..627550e 100644
--- a/common/pipeline.cpp
+++ b/common/pipeline.cpp
@@ -36,6 +36,9 @@
 #include "definitions.h"
 #include "bufferutils.h"
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "resource.pipeline"
+
 namespace Sink
 {
 
diff --git a/common/queryrunner.cpp b/common/queryrunner.cpp
index b49a3e0..63b5bcf 100644
--- a/common/queryrunner.cpp
+++ b/common/queryrunner.cpp
@@ -26,6 +26,9 @@
 #include "domainadaptor.h"
 #include "asyncutils.h"
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "client.queryrunner"
+
 using namespace Sink;
 
 /*
diff --git a/common/resourceaccess.cpp b/common/resourceaccess.cpp
index 2e87bc7..345622c 100644
--- a/common/resourceaccess.cpp
+++ b/common/resourceaccess.cpp
@@ -43,9 +43,10 @@
 #include <QBuffer>
 
 #undef Trace
-#define Trace() Sink::Log::debugStream(Sink::Log::DebugLevel::Trace, __LINE__, __FILE__, Q_FUNC_INFO, "ResourceAccess")
+#define TracePrivate() Trace_area("client.communication." + resourceInstanceIdentifier)
+#define Trace() Trace_area("client.communication." + d->resourceInstanceIdentifier)
 #undef Log
-#define Log(IDENTIFIER) Sink::Log::debugStream(Sink::Log::DebugLevel::Log, __LINE__, __FILE__, Q_FUNC_INFO, "ResourceAccess("+IDENTIFIER+")")
+#define Log() Log_area("client.communication." + d->resourceInstanceIdentifier)
 
 static void queuedInvoke(const std::function<void()> &f, QObject *context = 0)
 {
@@ -168,7 +169,7 @@ KAsync::Job<void> ResourceAccess::Private::tryToConnect()
         return !socket;
     },
     [this, counter](KAsync::Future<void> &future) {
-        Trace() << "Loop";
+        TracePrivate() << "Loop";
         KAsync::wait(50)
         .then(connectToServer(resourceInstanceIdentifier))
         .then<void, QSharedPointer<QLocalSocket> >([this, &future](const QSharedPointer<QLocalSocket> &s) {
@@ -176,10 +177,10 @@ KAsync::Job<void> ResourceAccess::Private::tryToConnect()
             socket = s;
             future.setFinished();
         },
-        [&future, counter](int errorCode, const QString &errorString) {
+        [&future, counter, this](int errorCode, const QString &errorString) {
             const int maxRetries = 10;
             if (*counter > maxRetries) {
-                Trace() << "Giving up";
+                TracePrivate() << "Giving up";
                 future.setError(-1, "Failed to connect to socket");
             } else {
                 future.setFinished();
@@ -192,21 +193,21 @@ KAsync::Job<void> ResourceAccess::Private::tryToConnect()
 KAsync::Job<void> ResourceAccess::Private::initializeSocket()
 {
     return KAsync::start<void>([this](KAsync::Future<void> &future) {
-        Trace() << "Trying to connect";
+        TracePrivate() << "Trying to connect";
         connectToServer(resourceInstanceIdentifier).then<void, QSharedPointer<QLocalSocket> >([this, &future](const QSharedPointer<QLocalSocket> &s) {
-            Trace() << "Connected to resource, without having to start it.";
+            TracePrivate() << "Connected to resource, without having to start it.";
             Q_ASSERT(s);
             socket = s;
             future.setFinished();
         },
         [this, &future](int errorCode, const QString &errorString) {
-            Trace() << "Failed to connect, starting resource";
+            TracePrivate() << "Failed to connect, starting resource";
             //We failed to connect, so let's start the resource
             QStringList args;
             args << resourceInstanceIdentifier;
             qint64 pid = 0;
             if (QProcess::startDetached("sink_synchronizer", args, QDir::homePath(), &pid)) {
-                Trace() << "Started resource " << pid;
+                TracePrivate() << "Started resource " << pid;
                 tryToConnect()
                 .then<void>([&future]() {
                     future.setFinished();
@@ -232,12 +233,12 @@ ResourceAccess::ResourceAccess(const QByteArray &resourceInstanceIdentifier)
     : ResourceAccessInterface(),
       d(new Private(getResourceName(resourceInstanceIdentifier), resourceInstanceIdentifier, this))
 {
-    log("Starting access");
+    Log() << "Starting access";
 }
 
 ResourceAccess::~ResourceAccess()
 {
-    log("Closing access");
+    Log() << "Closing access";
     if (!d->resultHandler.isEmpty()) {
         Warning() << "Left jobs running while shutting down ResourceAccess: " << d->resultHandler.keys();
     }
@@ -400,7 +401,7 @@ void ResourceAccess::open()
 
 void ResourceAccess::close()
 {
-    log(QString("Closing %1").arg(d->socket->fullServerName()));
+    Log() << QString("Closing %1").arg(d->socket->fullServerName());
     Trace() << "Pending commands: " << d->pendingCommands.size();
     Trace() << "Queued commands: " << d->commandQueue.size();
     d->socket->close();
@@ -412,7 +413,7 @@ void ResourceAccess::sendCommand(const QSharedPointer<QueuedCommand> &command)
     //TODO: we should have a timeout for commands
     d->messageId++;
     const auto messageId = d->messageId;
-    log(QString("Sending command \"%1\" with messageId %2").arg(QString(Sink::Commands::name(command->commandId))).arg(d->messageId));
+    Log() << QString("Sending command \"%1\" with messageId %2").arg(QString(Sink::Commands::name(command->commandId))).arg(d->messageId);
     Q_ASSERT(command->callback);
     registerCallback(d->messageId, [this, messageId, command](int errorCode, QString errorMessage) {
         Trace() << "Command complete " << messageId;
@@ -452,7 +453,7 @@ void ResourceAccess::connected()
         return;
     }
 
-    log(QString("Connected: %1").arg(d->socket->fullServerName()));
+    Log() << QString("Connected: %1").arg(d->socket->fullServerName());
 
     {
         flatbuffers::FlatBufferBuilder fbb;
@@ -472,7 +473,7 @@ void ResourceAccess::connected()
 
 void ResourceAccess::disconnected()
 {
-    log(QString("Disconnected from %1").arg(d->socket->fullServerName()));
+    Log() << QString("Disconnected from %1").arg(d->socket->fullServerName());
     d->socket->close();
     emit ready(false);
 }
@@ -480,7 +481,7 @@ void ResourceAccess::disconnected()
 void ResourceAccess::connectionError(QLocalSocket::LocalSocketError error)
 {
     if (error == QLocalSocket::PeerClosedError) {
-        Log(d->resourceInstanceIdentifier) << "The resource closed the connection.";
+        Log() << "The resource closed the connection.";
         d->abortPendingOperations();
     } else {
         Warning() << QString("Connection error: %1 : %2").arg(error).arg(d->socket->errorString());
@@ -524,14 +525,14 @@ bool ResourceAccess::processMessageBuffer()
     switch (commandId) {
         case Commands::RevisionUpdateCommand: {
             auto buffer = Commands::GetRevisionUpdate(d->partialMessageBuffer.constData() + headerSize);
-            log(QString("Revision updated to: %1").arg(buffer->revision()));
+            Log() << QString("Revision updated to: %1").arg(buffer->revision());
             emit revisionChanged(buffer->revision());
 
             break;
         }
         case Commands::CommandCompletionCommand: {
             auto buffer = Commands::GetCommandCompletion(d->partialMessageBuffer.constData() + headerSize);
-            log(QString("Command with messageId %1 completed %2").arg(buffer->id()).arg(buffer->success() ? "sucessfully" : "unsuccessfully"));
+            Log() << QString("Command with messageId %1 completed %2").arg(buffer->id()).arg(buffer->success() ? "sucessfully" : "unsuccessfully");
 
             d->completeCommands << buffer->id();
             //The callbacks can result in this object getting destroyed directly, so we need to ensure we finish our work first
@@ -544,11 +545,11 @@ bool ResourceAccess::processMessageBuffer()
             auto buffer = Commands::GetNotification(d->partialMessageBuffer.constData() + headerSize);
             switch (buffer->type()) {
                 case Sink::Commands::NotificationType::NotificationType_Shutdown:
-                    Log(d->resourceInstanceIdentifier) << "Received shutdown notification.";
+                    Log() << "Received shutdown notification.";
                     close();
                     break;
                 case Sink::Commands::NotificationType::NotificationType_Inspection: {
-                    Log(d->resourceInstanceIdentifier) << "Received inspection notification.";
+                    Log() << "Received inspection notification.";
                     Notification n;
                     if (buffer->identifier()) {
                         //Don't use fromRawData, the buffer is gone once we invoke emit notification
@@ -583,11 +584,6 @@ bool ResourceAccess::processMessageBuffer()
     return d->partialMessageBuffer.size() >= headerSize;
 }
 
-void ResourceAccess::log(const QString &message)
-{
-    Log(d->resourceInstanceIdentifier) << this << message;
-}
-
 }
 
 #pragma clang diagnostic push
diff --git a/common/resourceaccess.h b/common/resourceaccess.h
index d10363e..3acc886 100644
--- a/common/resourceaccess.h
+++ b/common/resourceaccess.h
@@ -101,7 +101,6 @@ private Q_SLOTS:
 
 private:
     void connected();
-    void log(const QString &message);
     void registerCallback(uint messageId, const std::function<void(int error, const QString &)> &callback);
 
     void sendCommand(const QSharedPointer<QueuedCommand> &command);
diff --git a/common/typeindex.cpp b/common/typeindex.cpp
index e58832c..b1bcf6a 100644
--- a/common/typeindex.cpp
+++ b/common/typeindex.cpp
@@ -22,6 +22,9 @@
 #include "index.h"
 #include <QDateTime>
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "common.typeindex"
+
 TypeIndex::TypeIndex(const QByteArray &type)
     : mType(type)
 {
diff --git a/docs/logging.md b/docs/logging.md
index a495a7a..3d5ea61 100644
--- a/docs/logging.md
+++ b/docs/logging.md
@@ -10,13 +10,34 @@ For debugging purposes a logging framework is required. Simple qDebugs() proved
     * logfiles
     * a commandline monitor tool
     * some other developer tool
+This way we get complete logs also if some resource was not started from the console (i.e. because it was already running).
 
 ## Debug levels
-* trace: trace individual codepaths. Likely outputs way to much information for all normal cases and likely is only ever temporarily enabled. Trace points are likely only inserted into code fragments that are known to be problematic.
+* trace: trace individual codepaths. Likely outputs way to much information for all normal cases and likely is only ever temporarily enabled for certain areas.
 * log: Comprehensive debug output. Enabled on demand
 * warning: Only warnings, should always be logged.
 * error: Critical messages that should never appear. Should always be logged.
 
+## Debug areas
+Debug areas split the code into sections that can be enabled/disabled as one.
+This is supposed to give finer grained control over what is logged or displayed.
+
+Debug areas may align with classes, but don't have to, the should be made so that they are useful.
+
+Areas could be:
+
+* resource.sync.performance
+* resource.sync
+* resource.listener
+* resource.pipeline
+* resource.store
+* resource.communication
+* client.communication
+* client.communication.org.sink.resource.maildir.identifier1
+* client.queryrunner
+* client.queryrunner.performance
+* common.typeindex
+
 ## Collected information
 Additionally to the regular message we want:
 
@@ -24,5 +45,5 @@ Additionally to the regular message we want:
 * threadid?
 * timestamp
 * sourcefile + position + function name
-* application name / resource identfier
-* component identifier (i.e. resource access)
+* application name / resource identifier
+* area (i.e. resource access)
diff --git a/examples/maildirresource/maildirresource.cpp b/examples/maildirresource/maildirresource.cpp
index cb51881..77ce11c 100644
--- a/examples/maildirresource/maildirresource.cpp
+++ b/examples/maildirresource/maildirresource.cpp
@@ -46,6 +46,9 @@
 #define ENTITY_TYPE_MAIL "mail"
 #define ENTITY_TYPE_FOLDER "folder"
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "resource.maildir"
+
 MaildirResource::MaildirResource(const QByteArray &instanceIdentifier, const QSharedPointer<Sink::Pipeline> &pipeline)
     : Sink::GenericResource(instanceIdentifier, pipeline),
     mMailAdaptorFactory(QSharedPointer<MaildirMailAdaptorFactory>::create()),
diff --git a/synchronizer/main.cpp b/synchronizer/main.cpp
index e9c17e7..d7a18e2 100644
--- a/synchronizer/main.cpp
+++ b/synchronizer/main.cpp
@@ -26,6 +26,9 @@
 #include "listener.h"
 #include "log.h"
 
+#undef DEBUG_AREA
+#define DEBUG_AREA "resource"
+
 void crashHandler(int sig) {
     std::fprintf(stderr, "Error: signal %d\n", sig);
 
@@ -70,6 +73,7 @@ int main(int argc, char *argv[])
     }
 
     const QByteArray instanceIdentifier = argv[1];
+    app.setApplicationName(instanceIdentifier);
 
     QLockFile lockfile(instanceIdentifier + ".lock");
     lockfile.setStaleLockTime(500);