From 3eac06de6e9a44d38e99cb748c125b4cd16bf670 Mon Sep 17 00:00:00 2001
From: Michael Zanetti <michael_zanetti@gmx.net>
Date: Fri, 15 Nov 2019 18:01:18 +0100
Subject: [PATCH 01/10] Threaded log database

This
a) makes the log db threaded by using QtConcurrent to run queries in a
different thread but still keeps ordering of the queries and always
only allows a single query at a time (QSql is not threadsafe). This fixes
removeDevice calls failing if we take more than $jsonprc_timeout to clean
a deleted device from the DB and keeps nymead responsive during that too.

b) generally improces performance of the system by not requiring operations
(emitting events, changing states) to wait for the sync log db entry to be
made.

c) drops some of the houskeeping code on nymea startup. While this will still
do log db housekeeping if the DB exceeds maxDbSize, it will not run
housekeeping on the DB any more at application startup. Reasoning for this
is that there have been reports of rules/log entries beimg destroyed if a
plugin can't be found at application startup. Given our general direction
of working towards more dynamic plugin loading, this might happen more often
in the future and we sure don't want to destroy rules etc when we just
temporarily miss a plugin.

d) tries to fix issue #226 by rotating the DB not only when it fails to open
initially, but also when it fails to insert new entries.
---
 libnymea-core/jsonrpc/logginghandler.cpp      |  31 ++-
 libnymea-core/logging/logengine.cpp           | 254 ++++++++++++------
 libnymea-core/logging/logengine.h             |  54 +++-
 libnymea-core/nymeacore.cpp                   |  22 --
 .../auto/loggingdirect/testloggingdirect.cpp  |  32 ++-
 tests/auto/rules/testrules.cpp                |  14 +-
 6 files changed, 277 insertions(+), 130 deletions(-)

diff --git a/libnymea-core/jsonrpc/logginghandler.cpp b/libnymea-core/jsonrpc/logginghandler.cpp
index c5b047bf..cf917b89 100644
--- a/libnymea-core/jsonrpc/logginghandler.cpp
+++ b/libnymea-core/jsonrpc/logginghandler.cpp
@@ -140,16 +140,27 @@ JsonReply* LoggingHandler::GetLogEntries(const QVariantMap &params) const
 {
     LogFilter filter = unpackLogFilter(params);
 
-    QVariantList entries;
-    foreach (const LogEntry &entry, NymeaCore::instance()->logEngine()->logEntries(filter)) {
-        entries.append(packLogEntry(entry));
-    }
-    QVariantMap returns;
-    returns.insert("loggingError", enumValueName<Logging::LoggingError>(Logging::LoggingErrorNoError));
-    returns.insert("logEntries", entries);
-    returns.insert("offset", filter.offset());
-    returns.insert("count", entries.count());
-    return createReply(returns);
+    LogEngineFetchJob *job = NymeaCore::instance()->logEngine()->logEntries(filter);
+
+    JsonReply *reply = createAsyncReply("GetLogEntries");
+
+    connect(job, &LogEngineFetchJob::finished, reply, [this, reply, job, filter](){
+
+        QVariantList entries;
+        foreach (const LogEntry &entry, job->results()) {
+            entries.append(packLogEntry(entry));
+        }
+        QVariantMap returns;
+        returns.insert("loggingError", enumValueName<Logging::LoggingError>(Logging::LoggingErrorNoError));
+        returns.insert("logEntries", entries);
+        returns.insert("offset", filter.offset());
+        returns.insert("count", entries.count());
+
+        reply->setData(returns);
+        reply->finished();
+    });
+
+    return reply;
 }
 
 QVariantMap LoggingHandler::packLogEntry(const LogEntry &logEntry)
diff --git a/libnymea-core/logging/logengine.cpp b/libnymea-core/logging/logengine.cpp
index 4faa9689..f1c99b16 100644
--- a/libnymea-core/logging/logengine.cpp
+++ b/libnymea-core/logging/logengine.cpp
@@ -128,6 +128,7 @@
 #include <QDateTime>
 #include <QFileInfo>
 #include <QTime>
+#include <QtConcurrent/QtConcurrent>
 
 #define DB_SCHEMA_VERSION 3
 
@@ -140,6 +141,8 @@ namespace nymeaserver {
 */
 LogEngine::LogEngine(const QString &driver, const QString &dbName, const QString &hostname, const QString &username, const QString &password, int maxDBSize, QObject *parent):
     QObject(parent),
+    m_username(username),
+    m_password(password),
     m_dbMaxSize(maxDBSize)
 {
     m_db = QSqlDatabase::addDatabase(driver, "logs");
@@ -169,11 +172,10 @@ LogEngine::LogEngine(const QString &driver, const QString &dbName, const QString
         }
     }
 
-    connect(&m_housekeepingTimer, &QTimer::timeout, this, &LogEngine::checkDBSize);
-    m_housekeepingTimer.setInterval(1); // Trigger on next idle event loop run
-    m_housekeepingTimer.setSingleShot(true);
-
     checkDBSize();
+
+    connect(&m_jobWatcher, SIGNAL(finished()), this, SLOT(handleJobFinished()));
+
 }
 
 /*! Destructs the \l{LogEngine}. */
@@ -186,7 +188,7 @@ LogEngine::~LogEngine()
 
   \sa LogEntry, LogFilter
 */
-QList<LogEntry> LogEngine::logEntries(const LogFilter &filter) const
+LogEngineFetchJob* LogEngine::logEntries(const LogFilter &filter)
 {
     QList<LogEntry> results;
     QSqlQuery query(m_db);
@@ -205,7 +207,7 @@ QList<LogEntry> LogEngine::logEntries(const LogFilter &filter) const
     } else {
         queryString = QString("SELECT * FROM entries WHERE %1 ORDER BY timestamp DESC %2;").arg(filter.queryString()).arg(limitString);
     }
-    qCDebug(dcLogEngine()) << "Preparing query:" << queryString;
+//    qCDebug(dcLogEngine()) << "Preparing query:" << queryString;
     query.prepare(queryString);
 
     foreach (const QString &value, filter.values()) {
@@ -213,29 +215,38 @@ QList<LogEntry> LogEngine::logEntries(const LogFilter &filter) const
         qCDebug(dcLogEngine()) << "Binding value to query:" << LogValueTool::serializeValue(value);
     }
 
-    query.exec();
+    DatabaseJob *job = new DatabaseJob(query, this);
+    LogEngineFetchJob *fetchJob = new LogEngineFetchJob(this);
 
-    if (m_db.lastError().isValid()) {
-        qCWarning(dcLogEngine) << "Error fetching log entries. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
-        return QList<LogEntry>();
-    }
+    connect(job, &DatabaseJob::finished, this, [this, job, fetchJob](){
+        fetchJob->deleteLater();
+        if (job->query().lastError().isValid()) {
+            qCWarning(dcLogEngine) << "Error fetching log entries. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+            fetchJob->finished();
+            return;
+        }
 
-    while (query.next()) {
-        LogEntry entry(
-                    QDateTime::fromTime_t(query.value("timestamp").toLongLong()),
-                    (Logging::LoggingLevel)query.value("loggingLevel").toInt(),
-                    (Logging::LoggingSource)query.value("sourceType").toInt(),
-                    query.value("errorCode").toInt());
-        entry.setTypeId(query.value("typeId").toUuid());
-        entry.setDeviceId(DeviceId(query.value("deviceId").toString()));
-        entry.setValue(LogValueTool::convertVariantToString(LogValueTool::deserializeValue(query.value("value").toString())));
-        entry.setEventType((Logging::LoggingEventType)query.value("loggingEventType").toInt());
-        entry.setActive(query.value("active").toBool());
-        results.append(entry);
-    }
-//    qCDebug(dcLogEngine) << "Fetched" << results.count() << "entries for db query:" << query.executedQuery();
+        while (job->query().next()) {
+            LogEntry entry(
+                        QDateTime::fromTime_t(job->query().value("timestamp").toLongLong()),
+                        (Logging::LoggingLevel)job->query().value("loggingLevel").toInt(),
+                        (Logging::LoggingSource)job->query().value("sourceType").toInt(),
+                        job->query().value("errorCode").toInt());
+            entry.setTypeId(job->query().value("typeId").toUuid());
+            entry.setDeviceId(DeviceId(job->query().value("deviceId").toString()));
+            entry.setValue(LogValueTool::convertVariantToString(LogValueTool::deserializeValue(job->query().value("value").toString())));
+            entry.setEventType((Logging::LoggingEventType)job->query().value("loggingEventType").toInt());
+            entry.setActive(job->query().value("active").toBool());
 
-    return results;
+            fetchJob->addResult(entry);
+        }
+        qCDebug(dcLogEngine) << "Fetched" << fetchJob->results().count() << "entries for db query:" << job->query().executedQuery();
+        fetchJob->finished();
+    });
+
+    enqueJob(job);
+
+    return fetchJob;
 }
 
 void LogEngine::setMaxLogEntries(int maxLogEntries, int overflow)
@@ -251,11 +262,18 @@ void LogEngine::clearDatabase()
     qCWarning(dcLogEngine) << "Clear logging database.";
 
     QString queryDeleteString = QString("DELETE FROM entries;");
-    if (m_db.exec(queryDeleteString).lastError().type() != QSqlError::NoError) {
-        qCWarning(dcLogEngine) << "Could not clear logging database. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
-    }
+    QSqlQuery query(queryDeleteString, m_db);
 
-    emit logDatabaseUpdated();
+    DatabaseJob *job = new DatabaseJob(query, this);
+
+    connect(job, &DatabaseJob::finished, this, [this, job](){
+        if (job->query().lastError().type() != QSqlError::NoError) {
+            qCWarning(dcLogEngine) << "Could not clear logging database. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+        }
+        emit logDatabaseUpdated();
+    });
+
+    enqueJob(job);
 }
 
 void LogEngine::logSystemEvent(const QDateTime &dateTime, bool active, Logging::LoggingLevel level)
@@ -378,11 +396,18 @@ void LogEngine::removeDeviceLogs(const DeviceId &deviceId)
     qCDebug(dcLogEngine) << "Deleting log entries from device" << deviceId.toString();
 
     QString queryDeleteString = QString("DELETE FROM entries WHERE deviceId = '%1';").arg(deviceId.toString());
-    if (m_db.exec(queryDeleteString).lastError().type() != QSqlError::NoError) {
-        qCWarning(dcLogEngine) << "Error deleting log entries from device" << deviceId.toString() << ". Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
-    } else {
-        emit logDatabaseUpdated();
-    }
+    QSqlQuery query(queryDeleteString, m_db);
+
+    DatabaseJob *job = new DatabaseJob(query, this);
+    connect(job, &DatabaseJob::finished, this, [this, job, deviceId](){
+        if (job->query().lastError().type() != QSqlError::NoError) {
+            qCWarning(dcLogEngine) << "Error deleting log entries from device" << deviceId.toString() << ". Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+        } else {
+            emit logDatabaseUpdated();
+        }
+    });
+
+    enqueJob(job);
 }
 
 void LogEngine::removeRuleLogs(const RuleId &ruleId)
@@ -390,29 +415,20 @@ void LogEngine::removeRuleLogs(const RuleId &ruleId)
     qCDebug(dcLogEngine) << "Deleting log entries from rule" << ruleId.toString();
 
     QString queryDeleteString = QString("DELETE FROM entries WHERE typeId = '%1';").arg(ruleId.toString());
-    if (m_db.exec(queryDeleteString).lastError().type() != QSqlError::NoError) {
-        qCWarning(dcLogEngine) << "Error deleting log entries from rule" << ruleId.toString() << ". Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
-    } else {
-        emit logDatabaseUpdated();
-    }
-}
+    QSqlQuery query(queryDeleteString, m_db);
 
-QList<DeviceId> LogEngine::devicesInLogs() const
-{
-    QString queryString = QString("SELECT deviceId FROM entries WHERE deviceId != \"%1\" GROUP BY deviceId;").arg(QUuid().toString());
-    QSqlQuery result = m_db.exec(queryString);
-    QList<DeviceId> ret;
-    if (result.lastError().type() != QSqlError::NoError) {
-        qCWarning(dcLogEngine()) << "Error fetching device entries from log database:" << m_db.lastError().driverText() << m_db.lastError().databaseText();
-        return ret;
-    }
-    if (!result.first()) {
-        return ret;
-    }
-    do {
-        ret.append(DeviceId::fromUuid(result.value("deviceId").toUuid()));
-    } while (result.next());
-    return ret;
+    DatabaseJob *job = new DatabaseJob(query, this);
+
+    connect(job, &DatabaseJob::finished, this, [this, job, ruleId](){
+
+        if (job->query().lastError().type() != QSqlError::NoError) {
+            qCWarning(dcLogEngine) << "Error deleting log entries from rule" << ruleId.toString() << ". Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+        } else {
+            emit logDatabaseUpdated();
+        }
+    });
+
+    enqueJob(job);
 }
 
 void LogEngine::appendLogEntry(const LogEntry &entry)
@@ -428,17 +444,28 @@ void LogEngine::appendLogEntry(const LogEntry &entry)
             .arg(entry.active())
             .arg(entry.errorCode());
 
-    if (m_db.exec(queryString).lastError().type() != QSqlError::NoError) {
-        qCWarning(dcLogEngine) << "Error writing log entry. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
-        qCWarning(dcLogEngine) << entry;
-        return;
-    }
+    QSqlQuery query(queryString, m_db);
 
-    emit logEntryAdded(entry);
+    DatabaseJob *job = new DatabaseJob(query, this);
 
-    if (++m_entryCount > m_dbMaxSize + m_overflow) {
-        m_housekeepingTimer.start();
-    }
+    connect(job, &DatabaseJob::finished, this, [this, job, entry](){
+
+        if (job->query().lastError().type() != QSqlError::NoError) {
+            qCWarning(dcLogEngine) << "Error writing log entry. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+            qCWarning(dcLogEngine) << entry;
+            m_dbMalformed = true;
+            processQueue();
+            return;
+        }
+
+        emit logEntryAdded(entry);
+
+        if (++m_entryCount > m_dbMaxSize + m_overflow) {
+            checkDBSize();
+        }
+    });
+
+    enqueJob(job);
 }
 
 void LogEngine::checkDBSize()
@@ -449,31 +476,92 @@ void LogEngine::checkDBSize()
     }
     QDateTime startTime = QDateTime::currentDateTime();
     QString queryString = "SELECT COUNT(*) FROM entries;";
-    QSqlQuery result = m_db.exec(queryString);
-    if (m_db.lastError().type() != QSqlError::NoError) {
-        qWarning(dcLogEngine()) << "Failed to query entry count in db:" << m_db.lastError().databaseText();
-        return;
-    }
-    if (!result.first()) {
-        qWarning(dcLogEngine()) << "Failed retrieving entry count.";
-        return;
-    }
-    m_entryCount = result.value(0).toInt();
 
-    if (m_entryCount >= m_dbMaxSize) {
+    QSqlQuery query(queryString, m_db);
+    DatabaseJob *job = new DatabaseJob(query, this);
+    connect(job, &DatabaseJob::finished, this, [this, job, startTime](){
+
+        QSqlQuery result = job->query();
+
+        if (m_db.lastError().type() != QSqlError::NoError) {
+            qWarning(dcLogEngine()) << "Failed to query entry count in db:" << m_db.lastError().databaseText();
+            return;
+        }
+        if (!result.first()) {
+            qWarning(dcLogEngine()) << "Failed retrieving entry count.";
+            return;
+        }
+        m_entryCount = result.value(0).toInt();
+
+        if (m_entryCount <= m_dbMaxSize) {
+            return;
+        }
+
         // keep only the latest m_dbMaxSize entries
         if (!m_trimWarningPrinted) {
             qCDebug(dcLogEngine) << "Deleting oldest entries" << (m_entryCount - m_dbMaxSize) << "and keep only the latest" << m_dbMaxSize << "entries.";
             m_trimWarningPrinted = true;
         }
         QString queryDeleteString = QString("DELETE FROM entries WHERE ROWID IN (SELECT ROWID FROM entries ORDER BY timestamp DESC LIMIT -1 OFFSET %1);").arg(QString::number(m_dbMaxSize));
-        if (m_db.exec(queryDeleteString).lastError().type() != QSqlError::NoError) {
-            qCWarning(dcLogEngine) << "Error deleting oldest log entries to keep size. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
-        }
-        m_entryCount = m_dbMaxSize;
-        emit logDatabaseUpdated();
+
+        QSqlQuery query(queryDeleteString);
+        DatabaseJob *deleteJob = new DatabaseJob(query, this);
+
+        connect(deleteJob, &DatabaseJob::finished, this, [this, deleteJob,startTime](){
+            if (deleteJob->query().lastError().type() != QSqlError::NoError) {
+                qCWarning(dcLogEngine) << "Error deleting oldest log entries to keep size. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+            }
+            m_entryCount = m_dbMaxSize;
+            qCDebug(dcLogEngine()) << "Ran housekeeping on log database in" << startTime.msecsTo(QDateTime::currentDateTime()) << "ms.";
+
+            emit logDatabaseUpdated();
+        });
+        enqueJob(deleteJob);
+    });
+    enqueJob(job);
+
+}
+
+void LogEngine::enqueJob(DatabaseJob *job)
+{
+    m_jobQueue.append(job);
+    processQueue();
+}
+
+void LogEngine::processQueue()
+{
+    if (m_jobQueue.isEmpty()) {
+        return;
     }
-    qCDebug(dcLogEngine()) << "Ran housekeeping on log database in" << startTime.msecsTo(QDateTime::currentDateTime()) << "ms.";
+
+    if (!m_jobWatcher.isFinished()) {
+        return;
+    }
+
+    if (m_dbMalformed) {
+        qCWarning(dcLogEngine()) << "Database is malformed. Trying to recover...";
+        m_db.close();
+        rotate(m_db.databaseName());
+        initDB(m_username, m_password);
+        m_dbMalformed = false;
+    }
+
+    DatabaseJob *job = m_jobQueue.takeFirst();
+
+    QFuture<DatabaseJob*> future = QtConcurrent::run([job](){
+        job->query().exec();
+        return job;
+    });
+
+    m_jobWatcher.setFuture(future);
+}
+
+void LogEngine::handleJobFinished()
+{
+    DatabaseJob *job = m_jobWatcher.result();
+    job->finished();
+    job->deleteLater();
+    processQueue();
 }
 
 void LogEngine::rotate(const QString &dbName)
diff --git a/libnymea-core/logging/logengine.h b/libnymea-core/logging/logengine.h
index 461bd98b..c906d323 100644
--- a/libnymea-core/logging/logengine.h
+++ b/libnymea-core/logging/logengine.h
@@ -32,18 +32,23 @@
 
 #include <QObject>
 #include <QSqlDatabase>
+#include <QSqlQuery>
 #include <QTimer>
+#include <QFutureWatcher>
 
 namespace nymeaserver {
 
+class DatabaseJob;
+class LogEngineFetchJob;
+
 class LogEngine: public QObject
 {
     Q_OBJECT
 public:
-    LogEngine(const QString &driver, const QString &dbName, const QString &hostname = QString("127.0.0.1"), const QString &username = QString(), const QString &password = QString(), int maxDBSize = 50000, QObject *parent = 0);
+    LogEngine(const QString &driver, const QString &dbName, const QString &hostname = QString("127.0.0.1"), const QString &username = QString(), const QString &password = QString(), int maxDBSize = 50000, QObject *parent = nullptr);
     ~LogEngine();
 
-    QList<LogEntry> logEntries(const LogFilter &filter = LogFilter()) const;
+    LogEngineFetchJob *logEntries(const LogFilter &filter = LogFilter());
 
     void setMaxLogEntries(int maxLogEntries, int overflow);
     void clearDatabase();
@@ -60,7 +65,6 @@ public:
     void logRuleExitActionsExecuted(const Rule &rule);
     void removeDeviceLogs(const DeviceId &deviceId);
     void removeRuleLogs(const RuleId &ruleId);
-    QList<DeviceId> devicesInLogs() const;
 
 signals:
     void logEntryAdded(const LogEntry &logEntry);
@@ -77,15 +81,57 @@ private:
 private slots:
     void checkDBSize();
 
+    void enqueJob(DatabaseJob *job);
+    void processQueue();
+    void handleJobFinished();
+
 private:
     QSqlDatabase m_db;
+    QString m_username;
+    QString m_password;
     int m_dbMaxSize;
     int m_overflow;
     bool m_trimWarningPrinted = false;
     int m_entryCount = 0;
-    QTimer m_housekeepingTimer;
+    bool m_dbMalformed = false;
+
+    QList<DatabaseJob*> m_jobQueue;
+    QFutureWatcher<DatabaseJob*> m_jobWatcher;
 };
 
+class DatabaseJob: public QObject
+{
+    Q_OBJECT
+public:
+    DatabaseJob(const QSqlQuery &query, QObject *parent): QObject(parent), m_query(query) {}
+
+    QSqlQuery query() const { return m_query; }
+
+signals:
+    void finished();
+
+private:
+    QSqlQuery m_query;
+};
+
+class LogEngineFetchJob: public QObject
+{
+    Q_OBJECT
+public:
+    LogEngineFetchJob(QObject *parent): QObject(parent) {}
+
+    QList<LogEntry> results() { return m_results; }
+
+signals:
+    void finished();
+
+private:
+    void addResult(const LogEntry &entry) { m_results.append(entry); }
+    QList<LogEntry> m_results;
+
+    friend class LogEngine;
+
+};
 }
 
 #endif
diff --git a/libnymea-core/nymeacore.cpp b/libnymea-core/nymeacore.cpp
index 44574b64..898f0f38 100644
--- a/libnymea-core/nymeacore.cpp
+++ b/libnymea-core/nymeacore.cpp
@@ -920,28 +920,6 @@ void NymeaCore::deviceManagerLoaded()
     onDateTimeChanged(m_timeManager->currentDateTime());
 
     emit initialized();
-
-    // Do some houskeeping...
-    qCDebug(dcApplication()) << "Starting housekeeping...";
-    QDateTime startTime = QDateTime::currentDateTime();
-    foreach (const DeviceId &deviceId, m_logger->devicesInLogs()) {
-        if (!m_deviceManager->findConfiguredDevice(deviceId)) {
-            qCDebug(dcApplication()) << "Cleaning stale device entries from log DB for device id" << deviceId;
-            m_logger->removeDeviceLogs(deviceId);
-        }
-    }
-
-    foreach (const DeviceId &deviceId, m_ruleEngine->devicesInRules()) {
-        if (!m_deviceManager->findConfiguredDevice(deviceId)) {
-            qCDebug(dcApplication()) << "Cleaning stale rule entries for device id" << deviceId;
-            foreach (const RuleId &ruleId, m_ruleEngine->findRules(deviceId)) {
-                m_ruleEngine->removeDeviceFromRule(ruleId, deviceId);
-            }
-        }
-    }
-
-    qCDebug(dcApplication()) << "Housekeeping done in" << startTime.msecsTo(QDateTime::currentDateTime()) << "ms.";
-
 }
 
 }
diff --git a/tests/auto/loggingdirect/testloggingdirect.cpp b/tests/auto/loggingdirect/testloggingdirect.cpp
index 810dbfe7..b5d2e4de 100644
--- a/tests/auto/loggingdirect/testloggingdirect.cpp
+++ b/tests/auto/loggingdirect/testloggingdirect.cpp
@@ -81,25 +81,43 @@ void TestLoggingDirect::benchmarkDB()
     qDebug() << "Flushing DB for test";
     engine->setMaxLogEntries(prefill, overflow);
     engine->setMaxLogEntries(maxSize, overflow);
-    qDebug() << "DB has" << engine->logEntries().count() << "entries";
+
+    LogEngineFetchJob *job = engine->logEntries();
+    QSignalSpy fetchSpy(job, &LogEngineFetchJob::finished);
+    fetchSpy.wait();
+    QList<LogEntry> entries = job->results();
+
+    qDebug() << "DB has" << entries.count() << "entries";
     qDebug() << "Prefilling DB for test";
-    for (int i = engine->logEntries().count(); i < prefill; i++) {
+    for (int i = entries.count(); i < prefill; i++) {
         engine->logSystemEvent(QDateTime::currentDateTime(), true);
     }
-    qDebug() << "DB has" << engine->logEntries().count() << "entries";
 
-    qDebug() << "Starting benchmark with" << engine->logEntries().count() << "entries in the db";
+    job = engine->logEntries();
+    QSignalSpy fetchSpy2(job, &LogEngineFetchJob::finished);
+    fetchSpy2.wait();
+    entries = job->results();
+
+    qDebug() << "DB has" << entries.count() << "entries";
+
+    qDebug() << "Starting benchmark with" << entries.count() << "entries in the db";
     QBENCHMARK {
         engine->logSystemEvent(QDateTime::currentDateTime(), true);
     }
     QDateTime now = QDateTime::currentDateTime();
-    while (engine->logEntries().count() > maxSize + overflow) {
+
+    job = engine->logEntries();
+    QSignalSpy fetchSpy3(job, &LogEngineFetchJob::finished);
+    fetchSpy3.wait();
+    entries = job->results();
+
+    while (entries.count() > maxSize + overflow) {
         qApp->processEvents();
         if (now.addSecs(5) < QDateTime::currentDateTime()) {
-            QVERIFY2(false, QString("Housekeeping didn't work. Have %1 entries but expected to have max %2").arg(engine->logEntries().count()).arg(QString::number(maxSize)).toLocal8Bit());
+            QVERIFY2(false, QString("Housekeeping didn't work. Have %1 entries but expected to have max %2").arg(entries.count()).arg(QString::number(maxSize)).toLocal8Bit());
         }
     }
-    qDebug() << "Ended benchmark with" << engine->logEntries().count() << "entries in the db";
+    qDebug() << "Ended benchmark with" << entries.count() << "entries in the db";
 }
 
 #include "testloggingdirect.moc"
diff --git a/tests/auto/rules/testrules.cpp b/tests/auto/rules/testrules.cpp
index 113664c9..b55e1a7a 100644
--- a/tests/auto/rules/testrules.cpp
+++ b/tests/auto/rules/testrules.cpp
@@ -2312,7 +2312,11 @@ void TestRules::testStateBasedAction()
     LogFilter filter;
     filter.addDeviceId(m_mockDeviceId);
     filter.addTypeId(mockWithParamsActionTypeId);
-    QList<LogEntry> entries = NymeaCore::instance()->logEngine()->logEntries(filter);
+
+    LogEngineFetchJob *job = NymeaCore::instance()->logEngine()->logEntries(filter);
+    QSignalSpy fetchSpy(job, &LogEngineFetchJob::finished);
+    fetchSpy.wait();
+    QList<LogEntry> entries = job->results();
     qCDebug(dcTests()) << "Log entries:" << entries;
 
     // set bool state to false
@@ -2331,10 +2335,12 @@ void TestRules::testStateBasedAction()
     QCOMPARE(spy.count(), 1);
     reply->deleteLater();
 
-    entries = NymeaCore::instance()->logEngine()->logEntries(filter);
+    job = NymeaCore::instance()->logEngine()->logEntries(filter);
+    QSignalSpy fetchSpy2(job, &LogEngineFetchJob::finished);
+    fetchSpy2.wait();
+    entries = job->results();
+
     qCDebug(dcTests()) << "Log entries:" << entries;
-
-
 }
 
 void TestRules::removePolicyUpdate()

From 2361cc0473376f0af68f23855a29a822167ab244 Mon Sep 17 00:00:00 2001
From: Michael Zanetti <michael_zanetti@gmx.net>
Date: Fri, 15 Nov 2019 18:20:26 +0100
Subject: [PATCH 02/10] Wait for the job queue to finish before shutting down

---
 libnymea-core/logging/logengine.cpp | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/libnymea-core/logging/logengine.cpp b/libnymea-core/logging/logengine.cpp
index f1c99b16..1af97270 100644
--- a/libnymea-core/logging/logengine.cpp
+++ b/libnymea-core/logging/logengine.cpp
@@ -172,15 +172,21 @@ LogEngine::LogEngine(const QString &driver, const QString &dbName, const QString
         }
     }
 
-    checkDBSize();
-
     connect(&m_jobWatcher, SIGNAL(finished()), this, SLOT(handleJobFinished()));
 
+    checkDBSize();
 }
 
 /*! Destructs the \l{LogEngine}. */
 LogEngine::~LogEngine()
 {
+    // Process the job queue before allowing to shut down
+    while (!m_jobQueue.isEmpty()) {
+        qApp->processEvents();
+    }
+    if (!m_jobWatcher.isFinished()) {
+        m_jobWatcher.waitForFinished();
+    }
     m_db.close();
 }
 

From f36eac080f6d0368542186ecf8452bacd03dd831 Mon Sep 17 00:00:00 2001
From: Michael Zanetti <michael_zanetti@gmx.net>
Date: Fri, 15 Nov 2019 23:12:27 +0100
Subject: [PATCH 03/10] fix duplicate query execution

---
 libnymea-core/logging/logengine.cpp | 25 +++++-------
 libnymea-core/logging/logengine.h   |  9 ++++-
 tests/auto/logging/testlogging.cpp  | 63 ++++++++++++++++++-----------
 tests/testlib/nymeatestbase.cpp     |  3 +-
 4 files changed, 59 insertions(+), 41 deletions(-)

diff --git a/libnymea-core/logging/logengine.cpp b/libnymea-core/logging/logengine.cpp
index 1af97270..e0364850 100644
--- a/libnymea-core/logging/logengine.cpp
+++ b/libnymea-core/logging/logengine.cpp
@@ -221,7 +221,7 @@ LogEngineFetchJob* LogEngine::logEntries(const LogFilter &filter)
         qCDebug(dcLogEngine()) << "Binding value to query:" << LogValueTool::serializeValue(value);
     }
 
-    DatabaseJob *job = new DatabaseJob(query, this);
+    DatabaseJob *job = new DatabaseJob(query);
     LogEngineFetchJob *fetchJob = new LogEngineFetchJob(this);
 
     connect(job, &DatabaseJob::finished, this, [this, job, fetchJob](){
@@ -268,9 +268,8 @@ void LogEngine::clearDatabase()
     qCWarning(dcLogEngine) << "Clear logging database.";
 
     QString queryDeleteString = QString("DELETE FROM entries;");
-    QSqlQuery query(queryDeleteString, m_db);
 
-    DatabaseJob *job = new DatabaseJob(query, this);
+    DatabaseJob *job = new DatabaseJob(queryDeleteString, m_db);
 
     connect(job, &DatabaseJob::finished, this, [this, job](){
         if (job->query().lastError().type() != QSqlError::NoError) {
@@ -402,9 +401,8 @@ void LogEngine::removeDeviceLogs(const DeviceId &deviceId)
     qCDebug(dcLogEngine) << "Deleting log entries from device" << deviceId.toString();
 
     QString queryDeleteString = QString("DELETE FROM entries WHERE deviceId = '%1';").arg(deviceId.toString());
-    QSqlQuery query(queryDeleteString, m_db);
 
-    DatabaseJob *job = new DatabaseJob(query, this);
+    DatabaseJob *job = new DatabaseJob(queryDeleteString, m_db);
     connect(job, &DatabaseJob::finished, this, [this, job, deviceId](){
         if (job->query().lastError().type() != QSqlError::NoError) {
             qCWarning(dcLogEngine) << "Error deleting log entries from device" << deviceId.toString() << ". Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
@@ -421,9 +419,8 @@ void LogEngine::removeRuleLogs(const RuleId &ruleId)
     qCDebug(dcLogEngine) << "Deleting log entries from rule" << ruleId.toString();
 
     QString queryDeleteString = QString("DELETE FROM entries WHERE typeId = '%1';").arg(ruleId.toString());
-    QSqlQuery query(queryDeleteString, m_db);
 
-    DatabaseJob *job = new DatabaseJob(query, this);
+    DatabaseJob *job = new DatabaseJob(queryDeleteString, m_db);
 
     connect(job, &DatabaseJob::finished, this, [this, job, ruleId](){
 
@@ -450,9 +447,7 @@ void LogEngine::appendLogEntry(const LogEntry &entry)
             .arg(entry.active())
             .arg(entry.errorCode());
 
-    QSqlQuery query(queryString, m_db);
-
-    DatabaseJob *job = new DatabaseJob(query, this);
+    DatabaseJob *job = new DatabaseJob(queryString, m_db);
 
     connect(job, &DatabaseJob::finished, this, [this, job, entry](){
 
@@ -483,18 +478,17 @@ void LogEngine::checkDBSize()
     QDateTime startTime = QDateTime::currentDateTime();
     QString queryString = "SELECT COUNT(*) FROM entries;";
 
-    QSqlQuery query(queryString, m_db);
-    DatabaseJob *job = new DatabaseJob(query, this);
+    DatabaseJob *job = new DatabaseJob(queryString, m_db);
     connect(job, &DatabaseJob::finished, this, [this, job, startTime](){
 
         QSqlQuery result = job->query();
 
         if (m_db.lastError().type() != QSqlError::NoError) {
-            qWarning(dcLogEngine()) << "Failed to query entry count in db:" << m_db.lastError().databaseText();
+            qCWarning(dcLogEngine()) << "Failed to query entry count in db:" << m_db.lastError().databaseText();
             return;
         }
         if (!result.first()) {
-            qWarning(dcLogEngine()) << "Failed retrieving entry count.";
+            qCWarning(dcLogEngine()) << "Failed retrieving entry count.";
             return;
         }
         m_entryCount = result.value(0).toInt();
@@ -510,8 +504,7 @@ void LogEngine::checkDBSize()
         }
         QString queryDeleteString = QString("DELETE FROM entries WHERE ROWID IN (SELECT ROWID FROM entries ORDER BY timestamp DESC LIMIT -1 OFFSET %1);").arg(QString::number(m_dbMaxSize));
 
-        QSqlQuery query(queryDeleteString);
-        DatabaseJob *deleteJob = new DatabaseJob(query, this);
+        DatabaseJob *deleteJob = new DatabaseJob(queryDeleteString, m_db);
 
         connect(deleteJob, &DatabaseJob::finished, this, [this, deleteJob,startTime](){
             if (deleteJob->query().lastError().type() != QSqlError::NoError) {
diff --git a/libnymea-core/logging/logengine.h b/libnymea-core/logging/logengine.h
index c906d323..31b37d3f 100644
--- a/libnymea-core/logging/logengine.h
+++ b/libnymea-core/logging/logengine.h
@@ -103,7 +103,14 @@ class DatabaseJob: public QObject
 {
     Q_OBJECT
 public:
-    DatabaseJob(const QSqlQuery &query, QObject *parent): QObject(parent), m_query(query) {}
+    DatabaseJob(const QString &queryString, const QSqlDatabase &db) {
+        m_query = QSqlQuery(db);
+        m_query.prepare(queryString);
+    }
+
+    // IMPORTANT: Make sure it only prepare()d but not executed
+    // QSQlQuery(QString, QSqlDatabase) implicitly executes!
+    DatabaseJob(const QSqlQuery &query): m_query(query) {}
 
     QSqlQuery query() const { return m_query; }
 
diff --git a/tests/auto/logging/testlogging.cpp b/tests/auto/logging/testlogging.cpp
index abd0753d..98e40a75 100644
--- a/tests/auto/logging/testlogging.cpp
+++ b/tests/auto/logging/testlogging.cpp
@@ -77,6 +77,7 @@ void TestLogging::initTestCase()
 {
     NymeaTestBase::initTestCase();
     QLoggingCategory::setFilterRules("*.debug=false\n"
+                                     "LogEngine.debug=true\n"
                                      "Tests.debug=true\n"
                                      "MockDevice.debug=true\n"
                                      "DeviceManager.debug=true\n");
@@ -88,8 +89,9 @@ void TestLogging::initLogs()
     verifyLoggingError(response);
 
     QVariantList logEntries = response.toMap().value("params").toMap().value("logEntries").toList();
-    qDebug() << "Got" << logEntries.count() << "logs";
-    QVERIFY(logEntries.count() > 0);
+    QVERIFY2(logEntries.count() > 0,
+             QString("Expected at least one log entry.")
+             .toUtf8());
 
     clearLoggingDatabase();
 
@@ -153,16 +155,34 @@ void TestLogging::coverageCalls()
 
 void TestLogging::systemLogs()
 {
-    // check the active system log at boot
+    qWarning() << "Clearing logging DB";
+    clearLoggingDatabase();
+
     QVariantMap params;
     params.insert("loggingSources", QVariantList() << enumValueName(Logging::LoggingSourceSystem));
     params.insert("eventTypes", QVariantList() << enumValueName(Logging::LoggingEventTypeActiveChange));
 
-    // there should be 2 logs, one for shutdown, one for startup (from server restart)
+    // there should be 0 log entries
     QVariant response = injectAndWait("Logging.GetLogEntries", params);
-    verifyLoggingError(response);
     QVariantList logEntries = response.toMap().value("params").toMap().value("logEntries").toList();
-    QVERIFY(logEntries.count() == 2);
+    QVERIFY2(logEntries.count() == 0,
+             QString("Expected 0 log entries but got:\n%1")
+             .arg(QString(QJsonDocument::fromVariant(logEntries).toJson()))
+             .toUtf8());
+
+    // check the active system log at boot
+    qWarning() << "Restarting server";
+    restartServer();
+    qWarning() << "Restart done";
+
+    // there should be 2 log entries, one for shutdown, one for startup (from server restart)
+    response = injectAndWait("Logging.GetLogEntries", params);
+    verifyLoggingError(response);
+    logEntries = response.toMap().value("params").toMap().value("logEntries").toList();
+    QVERIFY2(logEntries.count() == 2,
+             QString("Expected 2 log entries but got:\n%1")
+             .arg(QString(QJsonDocument::fromVariant(logEntries).toJson()))
+             .toUtf8());
 
     QVariantMap logEntryStartup = logEntries.first().toMap();
     QVariantMap logEntryShutdown = logEntries.last().toMap();
@@ -309,16 +329,19 @@ void TestLogging::actionLog()
     QVariant response = injectAndWait("Actions.ExecuteAction", params);
     verifyDeviceError(response);
 
-    // Lets wait for the notification
+    // wait for the outgoing data
+    // 3 packets: ExecuteAction reply,  LogDatabaseUpdated signal and LogEntryAdded signal
     clientSpy.wait(500);
+    if (clientSpy.count() < 3) {
+        clientSpy.wait(500);
+    }
 
-    QVariantList loggEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
-    QVERIFY2(!loggEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
-    qDebug() << "got" << loggEntryAddedVariants.count() << "Logging.LogEntryAdded notifications";
+    QVariantList logEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
+    qWarning() << QJsonDocument::fromVariant(logEntryAddedVariants).toJson();
+    QVERIFY2(!logEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
 
     bool found = false;
-    qDebug() << "got" << loggEntryAddedVariants.count() << "Logging.LogEntryAdded";
-    foreach (const QVariant &loggEntryAddedVariant, loggEntryAddedVariants) {
+    foreach (const QVariant &loggEntryAddedVariant, logEntryAddedVariants) {
         QVariantMap logEntry = loggEntryAddedVariant.toMap().value("params").toMap().value("logEntry").toMap();
         if (logEntry.value("deviceId").toUuid() == m_mockDeviceId) {
             found = true;
@@ -330,8 +353,6 @@ void TestLogging::actionLog()
             break;
         }
     }
-    if (!found)
-        qDebug() << QJsonDocument::fromVariant(loggEntryAddedVariants).toJson();
 
     QVERIFY2(found, "Could not find the corresponding Logging.LogEntryAdded notification");
 
@@ -344,8 +365,8 @@ void TestLogging::actionLog()
 
     clientSpy.wait(200);
 
-    loggEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
-    QVERIFY(!loggEntryAddedVariants.isEmpty());
+    logEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
+    QVERIFY(!logEntryAddedVariants.isEmpty());
 
     // get this logentry with filter
     params.clear();
@@ -371,13 +392,11 @@ void TestLogging::actionLog()
 
     clientSpy.wait(200);
 
-    loggEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
-    QVERIFY2(!loggEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
-    qDebug() << "got" << loggEntryAddedVariants.count() << "Logging.LogEntryAdded notifications";
+    logEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
+    QVERIFY2(!logEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
 
     found = false;
-    qDebug() << "got" << loggEntryAddedVariants.count() << "Logging.LogEntryAdded";
-    foreach (const QVariant &loggEntryAddedVariant, loggEntryAddedVariants) {
+    foreach (const QVariant &loggEntryAddedVariant, logEntryAddedVariants) {
         QVariantMap logEntry = loggEntryAddedVariant.toMap().value("params").toMap().value("logEntry").toMap();
         if (logEntry.value("deviceId").toUuid() == m_mockDeviceId) {
             found = true;
@@ -390,8 +409,6 @@ void TestLogging::actionLog()
             break;
         }
     }
-    if (!found)
-        qDebug() << QJsonDocument::fromVariant(loggEntryAddedVariants).toJson();
 
     QVERIFY2(found, "Could not find the corresponding Logging.LogEntryAdded notification");
 
diff --git a/tests/testlib/nymeatestbase.cpp b/tests/testlib/nymeatestbase.cpp
index 3ce0d52b..d03cd616 100644
--- a/tests/testlib/nymeatestbase.cpp
+++ b/tests/testlib/nymeatestbase.cpp
@@ -190,8 +190,9 @@ QVariantList NymeaTestBase::checkNotifications(const QSignalSpy &spy, const QStr
         // Make sure the response it a valid JSON string
         QJsonParseError error;
         QJsonDocument jsonDoc = QJsonDocument::fromJson(spy.at(i).last().toByteArray(), &error);
+//        qCDebug(dcTests()) << "Got packet:" << qUtf8Printable(jsonDoc.toJson());
         if (error.error != QJsonParseError::NoError) {
-            qWarning() << "JSON parser error" << error.errorString();
+            qCWarning(dcTests()) << "JSON parser error" << error.errorString();
             return notificationList;
         }
 

From 0ce99fc1272b9d1b0474c2797dab0eb9a2d06dbd Mon Sep 17 00:00:00 2001
From: Michael Zanetti <michael_zanetti@gmx.net>
Date: Fri, 15 Nov 2019 23:37:52 +0100
Subject: [PATCH 04/10] add some debugs

---
 libnymea-core/logging/logengine.cpp | 9 +++++----
 1 file changed, 5 insertions(+), 4 deletions(-)

diff --git a/libnymea-core/logging/logengine.cpp b/libnymea-core/logging/logengine.cpp
index e0364850..83855343 100644
--- a/libnymea-core/logging/logengine.cpp
+++ b/libnymea-core/logging/logengine.cpp
@@ -180,13 +180,14 @@ LogEngine::LogEngine(const QString &driver, const QString &dbName, const QString
 /*! Destructs the \l{LogEngine}. */
 LogEngine::~LogEngine()
 {
+    qWarning() << "Destroying logEngine";
     // Process the job queue before allowing to shut down
-    while (!m_jobQueue.isEmpty()) {
-        qApp->processEvents();
-    }
-    if (!m_jobWatcher.isFinished()) {
+    while (!m_jobQueue.isEmpty() || !m_jobWatcher.isFinished()) {
+        qWarning() << "Waiting for job to finish...";
         m_jobWatcher.waitForFinished();
     }
+    qWarning() << "Done waiting";
+    qCDebug(dcLogEngine()) << "Closing Database";
     m_db.close();
 }
 

From 73812df269e13d844ec0db8d50d2274ea1cf5c78 Mon Sep 17 00:00:00 2001
From: Michael Zanetti <michael_zanetti@gmx.net>
Date: Fri, 15 Nov 2019 23:54:40 +0100
Subject: [PATCH 05/10] fix shutdown

---
 libnymea-core/logging/logengine.cpp | 9 ++++++---
 libnymea-core/logging/logengine.h   | 1 +
 2 files changed, 7 insertions(+), 3 deletions(-)

diff --git a/libnymea-core/logging/logengine.cpp b/libnymea-core/logging/logengine.cpp
index 83855343..fd02919d 100644
--- a/libnymea-core/logging/logengine.cpp
+++ b/libnymea-core/logging/logengine.cpp
@@ -182,9 +182,10 @@ LogEngine::~LogEngine()
 {
     qWarning() << "Destroying logEngine";
     // Process the job queue before allowing to shut down
-    while (!m_jobQueue.isEmpty() || !m_jobWatcher.isFinished()) {
-        qWarning() << "Waiting for job to finish...";
+    while (m_currentJob) {
+        qWarning() << "Waiting for job to finish... (" << m_jobQueue.count() << "jobs left in queue)";
         m_jobWatcher.waitForFinished();
+        qApp->processEvents();
     }
     qWarning() << "Done waiting";
     qCDebug(dcLogEngine()) << "Closing Database";
@@ -534,7 +535,7 @@ void LogEngine::processQueue()
         return;
     }
 
-    if (!m_jobWatcher.isFinished()) {
+    if (m_currentJob) {
         return;
     }
 
@@ -547,6 +548,7 @@ void LogEngine::processQueue()
     }
 
     DatabaseJob *job = m_jobQueue.takeFirst();
+    m_currentJob = job;
 
     QFuture<DatabaseJob*> future = QtConcurrent::run([job](){
         job->query().exec();
@@ -561,6 +563,7 @@ void LogEngine::handleJobFinished()
     DatabaseJob *job = m_jobWatcher.result();
     job->finished();
     job->deleteLater();
+    m_currentJob = nullptr;
     processQueue();
 }
 
diff --git a/libnymea-core/logging/logengine.h b/libnymea-core/logging/logengine.h
index 31b37d3f..f3f9e02d 100644
--- a/libnymea-core/logging/logengine.h
+++ b/libnymea-core/logging/logengine.h
@@ -96,6 +96,7 @@ private:
     bool m_dbMalformed = false;
 
     QList<DatabaseJob*> m_jobQueue;
+    DatabaseJob *m_currentJob = nullptr;
     QFutureWatcher<DatabaseJob*> m_jobWatcher;
 };
 

From c7dd26d525383290d2fffc56aef677b085fada31 Mon Sep 17 00:00:00 2001
From: Michael Zanetti <michael_zanetti@gmx.net>
Date: Sat, 16 Nov 2019 00:44:08 +0100
Subject: [PATCH 06/10] cleanup, fix last tests

---
 libnymea-core/jsonrpc/logginghandler.cpp      |  4 +-
 libnymea-core/logging/logengine.cpp           | 42 ++++++++++++++-----
 libnymea-core/logging/logengine.h             | 30 ++++++++-----
 libnymea-core/nymeacore.cpp                   | 23 ++++++++++
 tests/auto/jsonrpc/testjsonrpc.cpp            | 16 +++----
 .../auto/loggingdirect/testloggingdirect.cpp  | 12 +++---
 tests/auto/rules/testrules.cpp                |  8 ++--
 7 files changed, 92 insertions(+), 43 deletions(-)

diff --git a/libnymea-core/jsonrpc/logginghandler.cpp b/libnymea-core/jsonrpc/logginghandler.cpp
index cf917b89..8e8a59d0 100644
--- a/libnymea-core/jsonrpc/logginghandler.cpp
+++ b/libnymea-core/jsonrpc/logginghandler.cpp
@@ -140,11 +140,11 @@ JsonReply* LoggingHandler::GetLogEntries(const QVariantMap &params) const
 {
     LogFilter filter = unpackLogFilter(params);
 
-    LogEngineFetchJob *job = NymeaCore::instance()->logEngine()->logEntries(filter);
+    LogEntriesFetchJob *job = NymeaCore::instance()->logEngine()->fetchLogEntries(filter);
 
     JsonReply *reply = createAsyncReply("GetLogEntries");
 
-    connect(job, &LogEngineFetchJob::finished, reply, [this, reply, job, filter](){
+    connect(job, &LogEntriesFetchJob::finished, reply, [reply, job, filter](){
 
         QVariantList entries;
         foreach (const LogEntry &entry, job->results()) {
diff --git a/libnymea-core/logging/logengine.cpp b/libnymea-core/logging/logengine.cpp
index fd02919d..f8e73b98 100644
--- a/libnymea-core/logging/logengine.cpp
+++ b/libnymea-core/logging/logengine.cpp
@@ -180,23 +180,19 @@ LogEngine::LogEngine(const QString &driver, const QString &dbName, const QString
 /*! Destructs the \l{LogEngine}. */
 LogEngine::~LogEngine()
 {
-    qWarning() << "Destroying logEngine";
     // Process the job queue before allowing to shut down
     while (m_currentJob) {
-        qWarning() << "Waiting for job to finish... (" << m_jobQueue.count() << "jobs left in queue)";
+        qCDebug(dcLogEngine()) << "Waiting for job to finish... (" << m_jobQueue.count() << "jobs left in queue)";
         m_jobWatcher.waitForFinished();
+        // Make sure that the job queue is processes
+        // We can't call processQueue ourselves because thread synchronisation is done via queued connections
         qApp->processEvents();
     }
-    qWarning() << "Done waiting";
     qCDebug(dcLogEngine()) << "Closing Database";
     m_db.close();
 }
 
-/*! Returns the list of \l{LogEntry}{LogEntries} of the database matching the given \a filter.
-
-  \sa LogEntry, LogFilter
-*/
-LogEngineFetchJob* LogEngine::logEntries(const LogFilter &filter)
+LogEntriesFetchJob *LogEngine::fetchLogEntries(const LogFilter &filter)
 {
     QList<LogEntry> results;
     QSqlQuery query(m_db);
@@ -224,7 +220,7 @@ LogEngineFetchJob* LogEngine::logEntries(const LogFilter &filter)
     }
 
     DatabaseJob *job = new DatabaseJob(query);
-    LogEngineFetchJob *fetchJob = new LogEngineFetchJob(this);
+    LogEntriesFetchJob *fetchJob = new LogEntriesFetchJob(this);
 
     connect(job, &DatabaseJob::finished, this, [this, job, fetchJob](){
         fetchJob->deleteLater();
@@ -246,7 +242,7 @@ LogEngineFetchJob* LogEngine::logEntries(const LogFilter &filter)
             entry.setEventType((Logging::LoggingEventType)job->query().value("loggingEventType").toInt());
             entry.setActive(job->query().value("active").toBool());
 
-            fetchJob->addResult(entry);
+            fetchJob->m_results.append(entry);
         }
         qCDebug(dcLogEngine) << "Fetched" << fetchJob->results().count() << "entries for db query:" << job->query().executedQuery();
         fetchJob->finished();
@@ -257,6 +253,32 @@ LogEngineFetchJob* LogEngine::logEntries(const LogFilter &filter)
     return fetchJob;
 }
 
+DevicesFetchJob *LogEngine::fetchDevices()
+{
+    QString queryString = QString("SELECT deviceId FROM entries WHERE deviceId != \"%1\" GROUP BY deviceId;").arg(QUuid().toString());
+
+    DatabaseJob *job = new DatabaseJob(queryString, m_db);
+    DevicesFetchJob *fetchJob = new DevicesFetchJob(this);
+    connect(job, &DatabaseJob::finished, this, [this, job, fetchJob](){
+        fetchJob->deleteLater();
+        if (job->query().lastError().type() != QSqlError::NoError) {
+            qCWarning(dcLogEngine()) << "Error fetching device entries from log database:" << m_db.lastError().driverText() << m_db.lastError().databaseText();
+            fetchJob->finished();
+            return;
+        }
+
+        if (!job->query().first()) {
+            fetchJob->finished();
+            return;
+        }
+        do {
+            fetchJob->m_results.append(DeviceId::fromUuid(job->query().value("deviceId").toUuid()));
+        } while (job->query().next());
+        fetchJob->finished();
+    });
+    return fetchJob;
+}
+
 void LogEngine::setMaxLogEntries(int maxLogEntries, int overflow)
 {
     m_dbMaxSize = maxLogEntries;
diff --git a/libnymea-core/logging/logengine.h b/libnymea-core/logging/logengine.h
index f3f9e02d..38c84281 100644
--- a/libnymea-core/logging/logengine.h
+++ b/libnymea-core/logging/logengine.h
@@ -39,7 +39,8 @@
 namespace nymeaserver {
 
 class DatabaseJob;
-class LogEngineFetchJob;
+class LogEntriesFetchJob;
+class DevicesFetchJob;
 
 class LogEngine: public QObject
 {
@@ -48,7 +49,8 @@ public:
     LogEngine(const QString &driver, const QString &dbName, const QString &hostname = QString("127.0.0.1"), const QString &username = QString(), const QString &password = QString(), int maxDBSize = 50000, QObject *parent = nullptr);
     ~LogEngine();
 
-    LogEngineFetchJob *logEntries(const LogFilter &filter = LogFilter());
+    LogEntriesFetchJob *fetchLogEntries(const LogFilter &filter = LogFilter());
+    DevicesFetchJob *fetchDevices();
 
     void setMaxLogEntries(int maxLogEntries, int overflow);
     void clearDatabase();
@@ -122,24 +124,32 @@ private:
     QSqlQuery m_query;
 };
 
-class LogEngineFetchJob: public QObject
+class LogEntriesFetchJob: public QObject
 {
     Q_OBJECT
 public:
-    LogEngineFetchJob(QObject *parent): QObject(parent) {}
-
+    LogEntriesFetchJob(QObject *parent): QObject(parent) {}
     QList<LogEntry> results() { return m_results; }
-
 signals:
     void finished();
-
 private:
-    void addResult(const LogEntry &entry) { m_results.append(entry); }
     QList<LogEntry> m_results;
-
     friend class LogEngine;
-
 };
+
+class DevicesFetchJob: public QObject
+{
+    Q_OBJECT
+public:
+    DevicesFetchJob(QObject *parent): QObject(parent) {}
+    QList<DeviceId> results() { return m_results; }
+signals:
+    void finished();
+private:
+    QList<DeviceId> m_results;
+    friend class LogEngine;
+};
+
 }
 
 #endif
diff --git a/libnymea-core/nymeacore.cpp b/libnymea-core/nymeacore.cpp
index 898f0f38..6c98bf9c 100644
--- a/libnymea-core/nymeacore.cpp
+++ b/libnymea-core/nymeacore.cpp
@@ -920,6 +920,29 @@ void NymeaCore::deviceManagerLoaded()
     onDateTimeChanged(m_timeManager->currentDateTime());
 
     emit initialized();
+
+    // Do some houskeeping...
+    qCDebug(dcApplication()) << "Starting housekeeping...";
+    QDateTime startTime = QDateTime::currentDateTime();
+    DevicesFetchJob *job = m_logger->fetchDevices();
+    connect(job, &DevicesFetchJob::finished, this, [this, job, startTime](){
+        foreach (const DeviceId &deviceId, job->results()) {
+            if (!m_deviceManager->findConfiguredDevice(deviceId)) {
+                qCDebug(dcApplication()) << "Cleaning stale device entries from log DB for device id" << deviceId;
+                m_logger->removeDeviceLogs(deviceId);
+            }
+        }
+        qCDebug(dcApplication()) << "Housekeeping done in" << startTime.msecsTo(QDateTime::currentDateTime()) << "ms.";
+    });
+
+    foreach (const DeviceId &deviceId, m_ruleEngine->devicesInRules()) {
+        if (!m_deviceManager->findConfiguredDevice(deviceId)) {
+            qCDebug(dcApplication()) << "Cleaning stale rule entries for device id" << deviceId;
+            foreach (const RuleId &ruleId, m_ruleEngine->findRules(deviceId)) {
+                m_ruleEngine->removeDeviceFromRule(ruleId, deviceId);
+            }
+        }
+    }
 }
 
 }
diff --git a/tests/auto/jsonrpc/testjsonrpc.cpp b/tests/auto/jsonrpc/testjsonrpc.cpp
index e1c69d14..5da756d5 100644
--- a/tests/auto/jsonrpc/testjsonrpc.cpp
+++ b/tests/auto/jsonrpc/testjsonrpc.cpp
@@ -991,18 +991,16 @@ void TestJSONRPC::stateChangeEmitsNotifications()
             break;
         }
     }
-    if (!found)
-        qDebug() << QJsonDocument::fromVariant(stateChangedVariants).toJson();
 
     QVERIFY2(found, "Could not find the correct Devices.StateChanged notification");
 
+    clientSpy.wait();
 
     // Make sure the logg notification contains all the stuff we expect
-    QVariantList loggEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
-    QVERIFY2(!loggEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
-    qDebug() << "got" << loggEntryAddedVariants.count() << "Logging.LogEntryAdded notifications";
+    QVariantList logEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
+    QVERIFY2(!logEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
     found = false;
-    foreach (const QVariant &loggEntryAddedVariant, loggEntryAddedVariants) {
+    foreach (const QVariant &loggEntryAddedVariant, logEntryAddedVariants) {
         if (loggEntryAddedVariant.toMap().value("params").toMap().value("logEntry").toMap().value("typeId").toUuid() == stateTypeId) {
             found = true;
             QCOMPARE(loggEntryAddedVariant.toMap().value("params").toMap().value("logEntry").toMap().value("source").toString(), QString("LoggingSourceStates"));
@@ -1010,8 +1008,6 @@ void TestJSONRPC::stateChangeEmitsNotifications()
             break;
         }
     }
-    if (!found)
-        qDebug() << QJsonDocument::fromVariant(loggEntryAddedVariants).toJson();
 
     QVERIFY2(found, "Could not find the corresponding Logging.LogEntryAdded notification");
 
@@ -1020,7 +1016,6 @@ void TestJSONRPC::stateChangeEmitsNotifications()
     QVariantList eventTriggeredVariants = checkNotifications(clientSpy, "Events.EventTriggered");
     QVERIFY2(!eventTriggeredVariants.isEmpty(), "Did not get Events.EventTriggered notification.");
     found = false;
-    qDebug() << "got" << eventTriggeredVariants.count() << "Events.EventTriggered notifications";
     foreach (const QVariant &eventTriggeredVariant, eventTriggeredVariants) {
         if (eventTriggeredVariant.toMap().value("params").toMap().value("event").toMap().value("eventTypeId").toUuid() == stateTypeId) {
             found = true;
@@ -1028,8 +1023,6 @@ void TestJSONRPC::stateChangeEmitsNotifications()
             break;
         }
     }
-    if (!found)
-        qDebug() << QJsonDocument::fromVariant(eventTriggeredVariants).toJson();
 
     QVERIFY2(found, "Could not find the corresponding Events.EventTriggered notification");
 
@@ -1108,6 +1101,7 @@ void TestJSONRPC::testPushButtonAuth()
 
 void TestJSONRPC::testPushButtonAuthInterrupt()
 {
+    enableNotifications({});
     PushButtonAgent pushButtonAgent;
     pushButtonAgent.init();
 
diff --git a/tests/auto/loggingdirect/testloggingdirect.cpp b/tests/auto/loggingdirect/testloggingdirect.cpp
index b5d2e4de..a1eb74f9 100644
--- a/tests/auto/loggingdirect/testloggingdirect.cpp
+++ b/tests/auto/loggingdirect/testloggingdirect.cpp
@@ -82,8 +82,8 @@ void TestLoggingDirect::benchmarkDB()
     engine->setMaxLogEntries(prefill, overflow);
     engine->setMaxLogEntries(maxSize, overflow);
 
-    LogEngineFetchJob *job = engine->logEntries();
-    QSignalSpy fetchSpy(job, &LogEngineFetchJob::finished);
+    LogEntriesFetchJob *job = engine->fetchLogEntries();
+    QSignalSpy fetchSpy(job, &LogEntriesFetchJob::finished);
     fetchSpy.wait();
     QList<LogEntry> entries = job->results();
 
@@ -93,8 +93,8 @@ void TestLoggingDirect::benchmarkDB()
         engine->logSystemEvent(QDateTime::currentDateTime(), true);
     }
 
-    job = engine->logEntries();
-    QSignalSpy fetchSpy2(job, &LogEngineFetchJob::finished);
+    job = engine->fetchLogEntries();
+    QSignalSpy fetchSpy2(job, &LogEntriesFetchJob::finished);
     fetchSpy2.wait();
     entries = job->results();
 
@@ -106,8 +106,8 @@ void TestLoggingDirect::benchmarkDB()
     }
     QDateTime now = QDateTime::currentDateTime();
 
-    job = engine->logEntries();
-    QSignalSpy fetchSpy3(job, &LogEngineFetchJob::finished);
+    job = engine->fetchLogEntries();
+    QSignalSpy fetchSpy3(job, &LogEntriesFetchJob::finished);
     fetchSpy3.wait();
     entries = job->results();
 
diff --git a/tests/auto/rules/testrules.cpp b/tests/auto/rules/testrules.cpp
index b55e1a7a..e390457e 100644
--- a/tests/auto/rules/testrules.cpp
+++ b/tests/auto/rules/testrules.cpp
@@ -2313,8 +2313,8 @@ void TestRules::testStateBasedAction()
     filter.addDeviceId(m_mockDeviceId);
     filter.addTypeId(mockWithParamsActionTypeId);
 
-    LogEngineFetchJob *job = NymeaCore::instance()->logEngine()->logEntries(filter);
-    QSignalSpy fetchSpy(job, &LogEngineFetchJob::finished);
+    LogEntriesFetchJob *job = NymeaCore::instance()->logEngine()->fetchLogEntries(filter);
+    QSignalSpy fetchSpy(job, &LogEntriesFetchJob::finished);
     fetchSpy.wait();
     QList<LogEntry> entries = job->results();
     qCDebug(dcTests()) << "Log entries:" << entries;
@@ -2335,8 +2335,8 @@ void TestRules::testStateBasedAction()
     QCOMPARE(spy.count(), 1);
     reply->deleteLater();
 
-    job = NymeaCore::instance()->logEngine()->logEntries(filter);
-    QSignalSpy fetchSpy2(job, &LogEngineFetchJob::finished);
+    job = NymeaCore::instance()->logEngine()->fetchLogEntries(filter);
+    QSignalSpy fetchSpy2(job, &LogEntriesFetchJob::finished);
     fetchSpy2.wait();
     entries = job->results();
 

From cee2ed154221f2b52d91d5097bb7bb535c7fa6b2 Mon Sep 17 00:00:00 2001
From: Michael Zanetti <michael_zanetti@gmx.net>
Date: Sat, 16 Nov 2019 00:52:25 +0100
Subject: [PATCH 07/10] make "make test" target work properly

---
 nymea.pro                | 5 +++--
 tests/auto/autotests.pri | 3 +++
 2 files changed, 6 insertions(+), 2 deletions(-)

diff --git a/nymea.pro b/nymea.pro
index 4d8ffca4..acd5e33d 100644
--- a/nymea.pro
+++ b/nymea.pro
@@ -58,8 +58,9 @@ INSTALLS += translations
 
 QMAKE_EXTRA_TARGETS += lupdate lrelease
 
-test.depends = licensecheck lrelease
-test.commands = LD_LIBRARY_PATH=$$top_builddir/libnymea-core:$$top_builddir/libnymea:$$top_builddir/tests/testlib make check
+test.depends = licensecheck
+test.depends += lrelease
+test.commands = LD_LIBRARY_PATH=$$top_builddir/libnymea-core:$$top_builddir/libnymea:$$top_builddir/tests/testlib make check TESTRUNNER=\"dbus-test-runner --bus-type=system --task\"
 QMAKE_EXTRA_TARGETS += test
 
 # Show doc files in project tree
diff --git a/tests/auto/autotests.pri b/tests/auto/autotests.pri
index e2f15432..64af8559 100644
--- a/tests/auto/autotests.pri
+++ b/tests/auto/autotests.pri
@@ -13,3 +13,6 @@ LIBS += -L$$top_builddir/libnymea/ -lnymea \
 
 target.path = /usr/tests
 INSTALLS += target
+
+test.commands = LD_LIBRARY_PATH=../../../libnymea:../../../libnymea-core/:../../testlib/ make check TESTRUNNER=\"dbus-test-runner --bus-type=system --task\"
+QMAKE_EXTRA_TARGETS += test

From 619bbf76f37426eb84433a2b710744cd3c02a59b Mon Sep 17 00:00:00 2001
From: Michael Zanetti <michael_zanetti@gmx.net>
Date: Thu, 28 Nov 2019 14:20:37 +0100
Subject: [PATCH 08/10] don't use QSqlQuery at all outside the job queue

On some backends, such as MySQL, a prepare() call will access
the database
---
 libnymea-core/logging/logengine.cpp | 121 +++++++++++++++-------------
 libnymea-core/logging/logengine.h   |  28 ++++---
 2 files changed, 85 insertions(+), 64 deletions(-)

diff --git a/libnymea-core/logging/logengine.cpp b/libnymea-core/logging/logengine.cpp
index f8e73b98..57a6142d 100644
--- a/libnymea-core/logging/logengine.cpp
+++ b/libnymea-core/logging/logengine.cpp
@@ -139,6 +139,13 @@ namespace nymeaserver {
     \a dbName is the name of the database. In case of SQLITE this should contain a file path. The Driver will create the file if required. In case of using a
     database server like MYSQL, the database must exist on the host given by \a hostname and be accessible with the given \a username and \a password.
 */
+
+// IMPORTANT:
+// DatabaseJobs run threaded, however, QSql is *not* threadsafe.
+// It is crucial to *not* access m_db while the job queue is being processed.
+// That is, entire setup of the DB must happen before processQueue() is called
+// and teardown must happen only after the job queue is empty.
+
 LogEngine::LogEngine(const QString &driver, const QString &dbName, const QString &hostname, const QString &username, const QString &password, int maxDBSize, QObject *parent):
     QObject(parent),
     m_username(username),
@@ -195,7 +202,6 @@ LogEngine::~LogEngine()
 LogEntriesFetchJob *LogEngine::fetchLogEntries(const LogFilter &filter)
 {
     QList<LogEntry> results;
-    QSqlQuery query(m_db);
 
     QString limitString;
     if (filter.limit() >= 0) {
@@ -211,40 +217,33 @@ LogEntriesFetchJob *LogEngine::fetchLogEntries(const LogFilter &filter)
     } else {
         queryString = QString("SELECT * FROM entries WHERE %1 ORDER BY timestamp DESC %2;").arg(filter.queryString()).arg(limitString);
     }
-//    qCDebug(dcLogEngine()) << "Preparing query:" << queryString;
-    query.prepare(queryString);
 
-    foreach (const QString &value, filter.values()) {
-        query.addBindValue(LogValueTool::serializeValue(value));
-        qCDebug(dcLogEngine()) << "Binding value to query:" << LogValueTool::serializeValue(value);
-    }
-
-    DatabaseJob *job = new DatabaseJob(query);
+    DatabaseJob *job = new DatabaseJob(m_db, queryString, filter.values());
     LogEntriesFetchJob *fetchJob = new LogEntriesFetchJob(this);
 
     connect(job, &DatabaseJob::finished, this, [this, job, fetchJob](){
         fetchJob->deleteLater();
-        if (job->query().lastError().isValid()) {
-            qCWarning(dcLogEngine) << "Error fetching log entries. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+        if (job->error().isValid()) {
+            qCWarning(dcLogEngine) << "Error fetching log entries. Driver error:" << job->error().driverText() << "Database error:" << job->error().databaseText();
             fetchJob->finished();
             return;
         }
 
-        while (job->query().next()) {
+        foreach (const QSqlRecord &result, job->results()) {
             LogEntry entry(
-                        QDateTime::fromTime_t(job->query().value("timestamp").toLongLong()),
-                        (Logging::LoggingLevel)job->query().value("loggingLevel").toInt(),
-                        (Logging::LoggingSource)job->query().value("sourceType").toInt(),
-                        job->query().value("errorCode").toInt());
-            entry.setTypeId(job->query().value("typeId").toUuid());
-            entry.setDeviceId(DeviceId(job->query().value("deviceId").toString()));
-            entry.setValue(LogValueTool::convertVariantToString(LogValueTool::deserializeValue(job->query().value("value").toString())));
-            entry.setEventType((Logging::LoggingEventType)job->query().value("loggingEventType").toInt());
-            entry.setActive(job->query().value("active").toBool());
+                        QDateTime::fromTime_t(result.value("timestamp").toUInt()),
+                        static_cast<Logging::LoggingLevel>(result.value("loggingLevel").toInt()),
+                        static_cast<Logging::LoggingSource>(result.value("sourceType").toInt()),
+                        result.value("errorCode").toInt());
+            entry.setTypeId(result.value("typeId").toUuid());
+            entry.setDeviceId(DeviceId(result.value("deviceId").toString()));
+            entry.setValue(LogValueTool::convertVariantToString(LogValueTool::deserializeValue(result.value("value").toString())));
+            entry.setEventType(static_cast<Logging::LoggingEventType>(result.value("loggingEventType").toInt()));
+            entry.setActive(result.value("active").toBool());
 
             fetchJob->m_results.append(entry);
         }
-        qCDebug(dcLogEngine) << "Fetched" << fetchJob->results().count() << "entries for db query:" << job->query().executedQuery();
+        qCDebug(dcLogEngine) << "Fetched" << fetchJob->results().count() << "entries for db query:" << job->executedQuery();
         fetchJob->finished();
     });
 
@@ -257,23 +256,19 @@ DevicesFetchJob *LogEngine::fetchDevices()
 {
     QString queryString = QString("SELECT deviceId FROM entries WHERE deviceId != \"%1\" GROUP BY deviceId;").arg(QUuid().toString());
 
-    DatabaseJob *job = new DatabaseJob(queryString, m_db);
+    DatabaseJob *job = new DatabaseJob(m_db, queryString);
     DevicesFetchJob *fetchJob = new DevicesFetchJob(this);
     connect(job, &DatabaseJob::finished, this, [this, job, fetchJob](){
         fetchJob->deleteLater();
-        if (job->query().lastError().type() != QSqlError::NoError) {
-            qCWarning(dcLogEngine()) << "Error fetching device entries from log database:" << m_db.lastError().driverText() << m_db.lastError().databaseText();
+        if (job->error().type() != QSqlError::NoError) {
+            qCWarning(dcLogEngine()) << "Error fetching device entries from log database:" << job->error().driverText() << job->error().databaseText();
             fetchJob->finished();
             return;
         }
 
-        if (!job->query().first()) {
-            fetchJob->finished();
-            return;
+        foreach (const QSqlRecord &result, job->results()) {
+            fetchJob->m_results.append(DeviceId::fromUuid(result.value("deviceId").toUuid()));
         }
-        do {
-            fetchJob->m_results.append(DeviceId::fromUuid(job->query().value("deviceId").toUuid()));
-        } while (job->query().next());
         fetchJob->finished();
     });
     return fetchJob;
@@ -293,11 +288,11 @@ void LogEngine::clearDatabase()
 
     QString queryDeleteString = QString("DELETE FROM entries;");
 
-    DatabaseJob *job = new DatabaseJob(queryDeleteString, m_db);
+    DatabaseJob *job = new DatabaseJob(m_db, queryDeleteString);
 
     connect(job, &DatabaseJob::finished, this, [this, job](){
-        if (job->query().lastError().type() != QSqlError::NoError) {
-            qCWarning(dcLogEngine) << "Could not clear logging database. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+        if (job->error().type() != QSqlError::NoError) {
+            qCWarning(dcLogEngine) << "Could not clear logging database. Driver error:" << job->error().driverText() << "Database error:" << job->error().databaseText();
         }
         emit logDatabaseUpdated();
     });
@@ -426,10 +421,10 @@ void LogEngine::removeDeviceLogs(const DeviceId &deviceId)
 
     QString queryDeleteString = QString("DELETE FROM entries WHERE deviceId = '%1';").arg(deviceId.toString());
 
-    DatabaseJob *job = new DatabaseJob(queryDeleteString, m_db);
+    DatabaseJob *job = new DatabaseJob(m_db, queryDeleteString);
     connect(job, &DatabaseJob::finished, this, [this, job, deviceId](){
-        if (job->query().lastError().type() != QSqlError::NoError) {
-            qCWarning(dcLogEngine) << "Error deleting log entries from device" << deviceId.toString() << ". Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+        if (job->error().type() != QSqlError::NoError) {
+            qCWarning(dcLogEngine) << "Error deleting log entries from device" << deviceId.toString() << ". Driver error:" << job->error().driverText() << "Database error:" << job->error().databaseText();
         } else {
             emit logDatabaseUpdated();
         }
@@ -444,12 +439,12 @@ void LogEngine::removeRuleLogs(const RuleId &ruleId)
 
     QString queryDeleteString = QString("DELETE FROM entries WHERE typeId = '%1';").arg(ruleId.toString());
 
-    DatabaseJob *job = new DatabaseJob(queryDeleteString, m_db);
+    DatabaseJob *job = new DatabaseJob(m_db, queryDeleteString);
 
     connect(job, &DatabaseJob::finished, this, [this, job, ruleId](){
 
-        if (job->query().lastError().type() != QSqlError::NoError) {
-            qCWarning(dcLogEngine) << "Error deleting log entries from rule" << ruleId.toString() << ". Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+        if (job->error().type() != QSqlError::NoError) {
+            qCWarning(dcLogEngine) << "Error deleting log entries from rule" << ruleId.toString() << ". Driver error:" << job->error().driverText() << "Database error:" << job->error().databaseText();
         } else {
             emit logDatabaseUpdated();
         }
@@ -471,12 +466,12 @@ void LogEngine::appendLogEntry(const LogEntry &entry)
             .arg(entry.active())
             .arg(entry.errorCode());
 
-    DatabaseJob *job = new DatabaseJob(queryString, m_db);
+    DatabaseJob *job = new DatabaseJob(m_db, queryString);
 
     connect(job, &DatabaseJob::finished, this, [this, job, entry](){
 
-        if (job->query().lastError().type() != QSqlError::NoError) {
-            qCWarning(dcLogEngine) << "Error writing log entry. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+        if (job->error().type() != QSqlError::NoError) {
+            qCWarning(dcLogEngine) << "Error writing log entry. Driver error:" << job->error().driverText() << "Database error:" << job->error().number() << job->error().databaseText();
             qCWarning(dcLogEngine) << entry;
             m_dbMalformed = true;
             processQueue();
@@ -502,20 +497,18 @@ void LogEngine::checkDBSize()
     QDateTime startTime = QDateTime::currentDateTime();
     QString queryString = "SELECT COUNT(*) FROM entries;";
 
-    DatabaseJob *job = new DatabaseJob(queryString, m_db);
+    DatabaseJob *job = new DatabaseJob(m_db, queryString);
     connect(job, &DatabaseJob::finished, this, [this, job, startTime](){
 
-        QSqlQuery result = job->query();
-
-        if (m_db.lastError().type() != QSqlError::NoError) {
-            qCWarning(dcLogEngine()) << "Failed to query entry count in db:" << m_db.lastError().databaseText();
+        if (job->error().type() != QSqlError::NoError) {
+            qCWarning(dcLogEngine()) << "Failed to query entry count in db:" << job->error().databaseText();
             return;
         }
-        if (!result.first()) {
+        if (job->results().isEmpty()) {
             qCWarning(dcLogEngine()) << "Failed retrieving entry count.";
             return;
         }
-        m_entryCount = result.value(0).toInt();
+        m_entryCount = job->results().first().value(0).toInt();
 
         if (m_entryCount <= m_dbMaxSize) {
             return;
@@ -528,11 +521,11 @@ void LogEngine::checkDBSize()
         }
         QString queryDeleteString = QString("DELETE FROM entries WHERE ROWID IN (SELECT ROWID FROM entries ORDER BY timestamp DESC LIMIT -1 OFFSET %1);").arg(QString::number(m_dbMaxSize));
 
-        DatabaseJob *deleteJob = new DatabaseJob(queryDeleteString, m_db);
+        DatabaseJob *deleteJob = new DatabaseJob(m_db, queryDeleteString);
 
         connect(deleteJob, &DatabaseJob::finished, this, [this, deleteJob,startTime](){
-            if (deleteJob->query().lastError().type() != QSqlError::NoError) {
-                qCWarning(dcLogEngine) << "Error deleting oldest log entries to keep size. Driver error:" << m_db.lastError().driverText() << "Database error:" << m_db.lastError().databaseText();
+            if (deleteJob->error().type() != QSqlError::NoError) {
+                qCWarning(dcLogEngine) << "Error deleting oldest log entries to keep size. Driver error:" << deleteJob->error().driverText() << "Database error:" << deleteJob->error().databaseText();
             }
             m_entryCount = m_dbMaxSize;
             qCDebug(dcLogEngine()) << "Ran housekeeping on log database in" << startTime.msecsTo(QDateTime::currentDateTime()) << "ms.";
@@ -573,8 +566,25 @@ void LogEngine::processQueue()
     m_currentJob = job;
 
     QFuture<DatabaseJob*> future = QtConcurrent::run([job](){
-        job->query().exec();
-        return job;
+        QSqlQuery query(job->m_db);
+        query.prepare(job->m_queryString);
+
+        foreach (const QString &value, job->m_bindValues) {
+            query.addBindValue(LogValueTool::serializeValue(value));
+        }
+
+        query.exec();
+
+        job->m_error = query.lastError();
+        job->m_executedQuery = query.executedQuery();
+
+        if (!query.lastError().isValid()) {
+            while (query.next()) {
+                job->m_results.append(query.record());
+            }
+        }
+
+       return job;
     });
 
     m_jobWatcher.setFuture(future);
@@ -752,6 +762,7 @@ bool LogEngine::initDB(const QString &username, const QString &password)
     }
 
     if (!m_db.tables().contains("entries")) {
+        qCDebug(dcLogEngine()) << "No \"entries\" table in database. Creating it.";
         m_db.exec("CREATE TABLE entries "
                   "("
                   "timestamp int,"
diff --git a/libnymea-core/logging/logengine.h b/libnymea-core/logging/logengine.h
index 38c84281..ef6113ff 100644
--- a/libnymea-core/logging/logengine.h
+++ b/libnymea-core/logging/logengine.h
@@ -33,6 +33,8 @@
 #include <QObject>
 #include <QSqlDatabase>
 #include <QSqlQuery>
+#include <QSqlError>
+#include <QSqlRecord>
 #include <QTimer>
 #include <QFutureWatcher>
 
@@ -106,22 +108,30 @@ class DatabaseJob: public QObject
 {
     Q_OBJECT
 public:
-    DatabaseJob(const QString &queryString, const QSqlDatabase &db) {
-        m_query = QSqlQuery(db);
-        m_query.prepare(queryString);
+    DatabaseJob(const QSqlDatabase &db, const QString &queryString, const QStringList &bindValues = QStringList()):
+        m_db(db),
+        m_queryString(queryString),
+        m_bindValues(bindValues)
+    {
     }
 
-    // IMPORTANT: Make sure it only prepare()d but not executed
-    // QSQlQuery(QString, QSqlDatabase) implicitly executes!
-    DatabaseJob(const QSqlQuery &query): m_query(query) {}
-
-    QSqlQuery query() const { return m_query; }
+    QString executedQuery() const { return m_executedQuery; }
+    QSqlError error() const { return m_error; }
+    QList<QSqlRecord> results() const { return m_results; }
 
 signals:
     void finished();
 
 private:
-    QSqlQuery m_query;
+    QSqlDatabase m_db;
+    QString m_queryString;
+    QStringList m_bindValues;
+
+    QString m_executedQuery;
+    QSqlError m_error;
+    QList<QSqlRecord> m_results;
+
+    friend class LogEngine;
 };
 
 class LogEntriesFetchJob: public QObject

From 64a494e44aee26645a4754622bc273370cec8b70 Mon Sep 17 00:00:00 2001
From: Michael Zanetti <michael_zanetti@gmx.net>
Date: Thu, 28 Nov 2019 20:47:55 +0100
Subject: [PATCH 09/10] Fix tests that didn't wait long enough for log entries
 to be written

---
 libnymea-core/logging/logengine.cpp |  8 ++++
 libnymea-core/logging/logengine.h   |  4 ++
 tests/auto/jsonrpc/testjsonrpc.cpp  | 62 +++++++++++++++++++++++++++--
 3 files changed, 70 insertions(+), 4 deletions(-)

diff --git a/libnymea-core/logging/logengine.cpp b/libnymea-core/logging/logengine.cpp
index 57a6142d..59595366 100644
--- a/libnymea-core/logging/logengine.cpp
+++ b/libnymea-core/logging/logengine.cpp
@@ -274,6 +274,11 @@ DevicesFetchJob *LogEngine::fetchDevices()
     return fetchJob;
 }
 
+bool LogEngine::jobsRunning() const
+{
+    return !m_jobQueue.isEmpty() || m_currentJob;
+}
+
 void LogEngine::setMaxLogEntries(int maxLogEntries, int overflow)
 {
     m_dbMaxSize = maxLogEntries;
@@ -547,6 +552,7 @@ void LogEngine::enqueJob(DatabaseJob *job)
 void LogEngine::processQueue()
 {
     if (m_jobQueue.isEmpty()) {
+        emit jobsRunningChanged();
         return;
     }
 
@@ -554,6 +560,8 @@ void LogEngine::processQueue()
         return;
     }
 
+    emit jobsRunningChanged();
+
     if (m_dbMalformed) {
         qCWarning(dcLogEngine()) << "Database is malformed. Trying to recover...";
         m_db.close();
diff --git a/libnymea-core/logging/logengine.h b/libnymea-core/logging/logengine.h
index ef6113ff..b15e7ddd 100644
--- a/libnymea-core/logging/logengine.h
+++ b/libnymea-core/logging/logengine.h
@@ -54,6 +54,8 @@ public:
     LogEntriesFetchJob *fetchLogEntries(const LogFilter &filter = LogFilter());
     DevicesFetchJob *fetchDevices();
 
+    bool jobsRunning() const;
+
     void setMaxLogEntries(int maxLogEntries, int overflow);
     void clearDatabase();
 
@@ -74,6 +76,8 @@ signals:
     void logEntryAdded(const LogEntry &logEntry);
     void logDatabaseUpdated();
 
+    void jobsRunningChanged();
+
 private:
     bool initDB(const QString &username, const QString &password);
     void appendLogEntry(const LogEntry &entry);
diff --git a/tests/auto/jsonrpc/testjsonrpc.cpp b/tests/auto/jsonrpc/testjsonrpc.cpp
index 5da756d5..d783e15f 100644
--- a/tests/auto/jsonrpc/testjsonrpc.cpp
+++ b/tests/auto/jsonrpc/testjsonrpc.cpp
@@ -41,6 +41,7 @@ private:
 
 private slots:
     void initTestCase();
+    void cleanup();
 
     void testHandshake();
 
@@ -148,6 +149,13 @@ void TestJSONRPC::initTestCase()
                                      "Tests.debug=true");
 }
 
+void TestJSONRPC::cleanup()
+{
+    while (NymeaCore::instance()->logEngine()->jobsRunning()) {
+        qApp->processEvents();
+    }
+}
+
 void TestJSONRPC::testHandshake()
 {
     QUuid newClientId = QUuid::createUuid();
@@ -846,16 +854,56 @@ void TestJSONRPC::ruleActiveChangedNotifications()
     QCOMPARE(notificationVariant.toMap().value("params").toMap().value("ruleId").toUuid().toString(), ruleId.toString());
     QCOMPARE(notificationVariant.toMap().value("params").toMap().value("active").toBool(), true);
 
+    clientSpy.wait();
+
+    // Make sure the logg notification contains all the stuff we expect
+    QVariantList logEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
+    QVERIFY2(!logEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
+    bool found = false;
+    foreach (const QVariant &loggEntryAddedVariant, logEntryAddedVariants) {
+        if (loggEntryAddedVariant.toMap().value("params").toMap().value("logEntry").toMap().value("typeId").toUuid() == mockIntStateTypeId) {
+            found = true;
+            QCOMPARE(loggEntryAddedVariant.toMap().value("params").toMap().value("logEntry").toMap().value("source").toString(), QString("LoggingSourceStates"));
+            QCOMPARE(loggEntryAddedVariant.toMap().value("params").toMap().value("logEntry").toMap().value("value").toInt(), 20);
+            break;
+        }
+    }
+    QVERIFY2(found, "LogEntryAdded notification not received");
+
     spy.clear(); clientSpy.clear();
 
     // set the rule inactive
     qDebug() << "setting mock int state to 42";
     QNetworkRequest request2(QUrl(QString("http://localhost:%1/setstate?%2=%3").arg(m_mockDevice1Port).arg(mockIntStateTypeId.toString()).arg(42)));
     QNetworkReply *reply2 = nam.get(request2);
-    if (spy.count() == 0) spy.wait();
-    QCOMPARE(spy.count(), 1);
     connect(reply2, SIGNAL(finished()), reply2, SLOT(deleteLater()));
 
+    // Waiting for notifications:
+    // Devices.StateChanged for the change we did
+    // Devices.EventTriggered
+    // Events.EventTriggered <-- deprecated
+    // Rules.RuleActiveChanged
+    // Logging.LogEntryAdded
+    // Devices.StateChanged for the change done by the rule
+    // Devices.EventTriggered
+    // Events.EventTriggered <-- deprecated
+    while (clientSpy.count() < 8) {
+        clientSpy.wait();
+    }
+
+    // Make sure the logg notification contains all the stuff we expect
+    logEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
+    QVERIFY2(!logEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
+    found = false;
+    foreach (const QVariant &loggEntryAddedVariant, logEntryAddedVariants) {
+        if (loggEntryAddedVariant.toMap().value("params").toMap().value("logEntry").toMap().value("typeId").toUuid() == mockIntStateTypeId) {
+            found = true;
+            QCOMPARE(loggEntryAddedVariant.toMap().value("params").toMap().value("logEntry").toMap().value("source").toString(), QString("LoggingSourceStates"));
+            QCOMPARE(loggEntryAddedVariant.toMap().value("params").toMap().value("logEntry").toMap().value("value").toInt(), 42);
+            break;
+        }
+    }
+    QVERIFY2(found, "LogEntryAdded notification not received");
 
     if (clientSpy.count() == 0) clientSpy.wait();
     notificationVariant = checkNotification(clientSpy, "Rules.RuleActiveChanged");
@@ -994,7 +1042,14 @@ void TestJSONRPC::stateChangeEmitsNotifications()
 
     QVERIFY2(found, "Could not find the correct Devices.StateChanged notification");
 
-    clientSpy.wait();
+    // Waiting for:
+    // Devices.StateChanged
+    // Devices.EventTriggered
+    // Events.EventTriggered <-- deprecated
+    // Logging.LogEntryAdded
+    while (clientSpy.count() < 4) {
+        clientSpy.wait();
+    }
 
     // Make sure the logg notification contains all the stuff we expect
     QVariantList logEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
@@ -1011,7 +1066,6 @@ void TestJSONRPC::stateChangeEmitsNotifications()
 
     QVERIFY2(found, "Could not find the corresponding Logging.LogEntryAdded notification");
 
-
     // Make sure the notification contains all the stuff we expect
     QVariantList eventTriggeredVariants = checkNotifications(clientSpy, "Events.EventTriggered");
     QVERIFY2(!eventTriggeredVariants.isEmpty(), "Did not get Events.EventTriggered notification.");

From 212ccc8596a02fcfc843957b6f89b298ef7d1126 Mon Sep 17 00:00:00 2001
From: Michael Zanetti <michael_zanetti@gmx.net>
Date: Sat, 30 Nov 2019 23:56:56 +0100
Subject: [PATCH 10/10] remove unneeded processQueue

---
 libnymea-core/logging/logengine.cpp | 1 -
 tests/scripts/gettags.sh            | 8 ++++++--
 2 files changed, 6 insertions(+), 3 deletions(-)

diff --git a/libnymea-core/logging/logengine.cpp b/libnymea-core/logging/logengine.cpp
index 59595366..c205ab1e 100644
--- a/libnymea-core/logging/logengine.cpp
+++ b/libnymea-core/logging/logengine.cpp
@@ -479,7 +479,6 @@ void LogEngine::appendLogEntry(const LogEntry &entry)
             qCWarning(dcLogEngine) << "Error writing log entry. Driver error:" << job->error().driverText() << "Database error:" << job->error().number() << job->error().databaseText();
             qCWarning(dcLogEngine) << entry;
             m_dbMalformed = true;
-            processQueue();
             return;
         }
 
diff --git a/tests/scripts/gettags.sh b/tests/scripts/gettags.sh
index a06c5f52..fa0a08b4 100755
--- a/tests/scripts/gettags.sh
+++ b/tests/scripts/gettags.sh
@@ -2,6 +2,10 @@
 
 if [ -z $1 ]; then
   echo "usage: $0 host"
-else
-  (echo '{"id":1, "method":"Tags.GetTags"}'; sleep 1) | nc $1 2222
+  exit 1
 fi
+
+cat << EOD | nc $1 2222
+{"id":0, "method":"JSONRPC.Hello"}
+{"id":1, "method":"Tags.GetTags"}
+EOD