fix duplicate query execution

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(queryString, m_db);
-
-    DatabaseJob *job = new DatabaseJob(query, this);
 
     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(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();
+            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(queryDeleteString, m_db);
-        DatabaseJob *deleteJob = new DatabaseJob(query, this);
 
         connect(deleteJob, &DatabaseJob::finished, this, [this, deleteJob,startTime](){
             if (deleteJob->query().lastError().type() != QSqlError::NoError) {

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; }
 

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";
+    QVERIFY2(logEntries.count() > 0,
-    QVERIFY(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");
+    QVariantList logEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
-    QVERIFY2(!loggEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
+    qWarning() << QJsonDocument::fromVariant(logEntryAddedVariants).toJson();
-    qDebug() << "got" << loggEntryAddedVariants.count() << "Logging.LogEntryAdded notifications";
+    QVERIFY2(!logEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
 
     bool found = false;
-    qDebug() << "got" << loggEntryAddedVariants.count() << "Logging.LogEntryAdded";
+    foreach (const QVariant &loggEntryAddedVariant, logEntryAddedVariants) {
-    foreach (const QVariant &loggEntryAddedVariant, loggEntryAddedVariants) {
         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");
+    logEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
-    QVERIFY(!loggEntryAddedVariants.isEmpty());
+    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");
+    logEntryAddedVariants = checkNotifications(clientSpy, "Logging.LogEntryAdded");
-    QVERIFY2(!loggEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
+    QVERIFY2(!logEntryAddedVariants.isEmpty(), "Did not get Logging.LogEntryAdded notification.");
-    qDebug() << "got" << loggEntryAddedVariants.count() << "Logging.LogEntryAdded notifications";
 
     found = false;
-    qDebug() << "got" << loggEntryAddedVariants.count() << "Logging.LogEntryAdded";
+    foreach (const QVariant &loggEntryAddedVariant, logEntryAddedVariants) {
-    foreach (const QVariant &loggEntryAddedVariant, loggEntryAddedVariants) {
         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");
 

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;
         }