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