From 5a36c2347f60aae673053814ac7ff7102dcf874d Mon Sep 17 00:00:00 2001 From: Michael Zanetti Date: Thu, 28 Nov 2019 12:09:50 +0100 Subject: [PATCH] fix logging system to cope with the qml output redirection --- libnymea-core/debugserverhandler.cpp | 10 +-- libnymea-core/debugserverhandler.h | 1 - libnymea-core/scriptengine/scriptengine.cpp | 73 +++++++++++++--- libnymea-core/scriptengine/scriptengine.h | 6 +- libnymea/loggingcategories.cpp | 92 +++++++++++++++++++++ libnymea/loggingcategories.h | 19 +++++ server/main.cpp | 74 ++--------------- tests/auto/jsonrpc/testjsonrpc.cpp | 2 +- 8 files changed, 189 insertions(+), 88 deletions(-) diff --git a/libnymea-core/debugserverhandler.cpp b/libnymea-core/debugserverhandler.cpp index 2b71eb95..103b3a78 100644 --- a/libnymea-core/debugserverhandler.cpp +++ b/libnymea-core/debugserverhandler.cpp @@ -41,7 +41,6 @@ namespace nymeaserver { -QtMessageHandler DebugServerHandler::s_oldLogMessageHandler = nullptr; QList DebugServerHandler::s_websocketClients; DebugServerHandler::DebugServerHandler(QObject *parent) : @@ -514,8 +513,6 @@ HttpReply *DebugServerHandler::processDebugRequest(const QString &requestPath, c void DebugServerHandler::logMessageHandler(QtMsgType type, const QMessageLogContext &context, const QString &message) { - s_oldLogMessageHandler(type, context, message); - QString finalMessage; switch (type) { case QtDebugMsg: @@ -616,7 +613,7 @@ void DebugServerHandler::onWebsocketClientConnected() if (s_websocketClients.isEmpty()) { qCDebug(dcDebugServer()) << "Install debug message handler for live logs."; //QLoggingCategory::setFilterRules("*.debug=true"); - s_oldLogMessageHandler = qInstallMessageHandler(&logMessageHandler); + nymeaInstallMessageHandler(&logMessageHandler); } s_websocketClients.append(client); @@ -634,9 +631,8 @@ void DebugServerHandler::onWebsocketClientDisconnected() client->deleteLater(); if (s_websocketClients.isEmpty()) { - qCDebug(dcDebugServer()) << "Uninstall debug message handler for live logs and restore default message handler"; - qInstallMessageHandler(s_oldLogMessageHandler); - s_oldLogMessageHandler = nullptr; + qCDebug(dcDebugServer()) << "Uninstalling debug message handler for live logs."; + nymeaUninstallMessageHandler(&logMessageHandler); } } diff --git a/libnymea-core/debugserverhandler.h b/libnymea-core/debugserverhandler.h index 9a701d4f..034865b7 100644 --- a/libnymea-core/debugserverhandler.h +++ b/libnymea-core/debugserverhandler.h @@ -41,7 +41,6 @@ public: HttpReply *processDebugRequest(const QString &requestPath, const QUrlQuery &requestQuery); private: - static QtMessageHandler s_oldLogMessageHandler; static QList s_websocketClients; static void logMessageHandler(QtMsgType type, const QMessageLogContext &context, const QString &message); diff --git a/libnymea-core/scriptengine/scriptengine.cpp b/libnymea-core/scriptengine/scriptengine.cpp index a0221dd9..51d6f694 100644 --- a/libnymea-core/scriptengine/scriptengine.cpp +++ b/libnymea-core/scriptengine/scriptengine.cpp @@ -39,23 +39,43 @@ namespace nymeaserver { -QtMessageHandler ScriptEngine::s_upstreamMessageHandler; QList ScriptEngine::s_engines; +QtMessageHandler ScriptEngine::s_upstreamMessageHandler; +QLoggingCategory::CategoryFilter ScriptEngine::s_oldCategoryFilter = nullptr; ScriptEngine::ScriptEngine(DeviceManager *deviceManager, QObject *parent) : QObject(parent), m_deviceManager(deviceManager) { + qmlRegisterType("nymea", 1, 0, "DeviceEvent"); + qmlRegisterType("nymea", 1, 0, "DeviceAction"); + qmlRegisterType("nymea", 1, 0, "DeviceState"); + + m_engine = new QQmlEngine(this); + m_engine->setProperty("deviceManager", reinterpret_cast(m_deviceManager)); + + // Don't automatically print script warnings (that is, runtime errors, *not* console.warn() messages) + // to stdout as they'd end up on the "default" logging category. + // We collect them ourselves through the warnings() signal and print them to the dcScriptEngine category. + m_engine->setOutputWarningsToStandardError(false); + connect(m_engine, &QQmlEngine::warnings, this, [this](const QList &warnings){ + foreach (const QQmlError &warning, warnings) { + QMessageLogContext ctx(warning.url().toString().toUtf8(), warning.line(), "", "ScriptEngine"); + // Send to script logs + onScriptMessage(warning.messageType(), ctx, warning.description()); + // and to logging system + qCWarning(dcScriptEngine()) << warning.toString(); + } + }); + + // console.log()/warn() messages instead are printed to the "qml" category. We install our own + // filter to *always* get them, regardless of the configured logging categories + s_oldCategoryFilter = QLoggingCategory::installFilter(&logCategoryFilter); + // and our own handler to redirect them to the ScriptEngine category if (s_engines.isEmpty()) { s_upstreamMessageHandler = qInstallMessageHandler(&logMessageHandler); } s_engines.append(this); - qmlRegisterType("nymea", 1, 0, "DeviceEvent"); - qmlRegisterType("nymea", 1, 0, "DeviceAction"); - qmlRegisterType("nymea", 1, 0, "DeviceState"); - - m_engine = new QQmlApplicationEngine(this); - m_engine->setProperty("deviceManager", reinterpret_cast(m_deviceManager)); QDir dir; if (!dir.exists(NymeaSettings::storagePath() + "/scripts/")) { @@ -395,17 +415,44 @@ void ScriptEngine::onScriptMessage(QtMsgType type, const QMessageLogContext &con if (!m_scripts.contains(scriptId)) { return; } - emit scriptConsoleMessage(scriptId, type == QtDebugMsg ? ScriptMessageTypeLog : ScriptMessageTypeWarning, message); + emit scriptConsoleMessage(scriptId, type == QtDebugMsg ? ScriptMessageTypeLog : ScriptMessageTypeWarning, QString::number(context.line) + ": " + message); } void ScriptEngine::logMessageHandler(QtMsgType type, const QMessageLogContext &context, const QString &message) { - if (strcmp(context.category, "qml") == 0) { - foreach (ScriptEngine *engine, s_engines) { - engine->onScriptMessage(type, context, message); - } + if (strcmp(context.category, "qml") != 0) { + s_upstreamMessageHandler(type, context, message); + return; + } + + // Copy the message to the script engine + foreach (ScriptEngine *engine, s_engines) { + engine->onScriptMessage(type, context, message); + } + + if (!s_oldCategoryFilter) { + return; + } + + // Redirect qml messages to the ScriptEngine handler + QMessageLogContext newContext(context.file, context.line, context.function, "ScriptEngine"); + QLoggingCategory *category = new QLoggingCategory("ScriptEngine", type); + s_oldCategoryFilter(category); + if (category->isEnabled(type)) { + QFileInfo fi(context.file); + s_upstreamMessageHandler(type, newContext, fi.fileName() + ":" + QString::number(context.line) + ": " + message); + } +} + +void ScriptEngine::logCategoryFilter(QLoggingCategory *category) +{ + // always enable qml logs, regardless what the filters are + if (qstrcmp(category->categoryName(), "qml") == 0) { + category->setEnabled(QtDebugMsg, true); + category->setEnabled(QtWarningMsg, true); + } else if (s_oldCategoryFilter) { + s_oldCategoryFilter(category); } - s_upstreamMessageHandler(type, context, message); } } diff --git a/libnymea-core/scriptengine/scriptengine.h b/libnymea-core/scriptengine/scriptengine.h index 601350ff..32a59446 100644 --- a/libnymea-core/scriptengine/scriptengine.h +++ b/libnymea-core/scriptengine/scriptengine.h @@ -24,6 +24,8 @@ #include #include #include +#include +#include #include "devices/devicemanager.h" #include "script.h" @@ -94,9 +96,11 @@ private: QHash m_scripts; - static QtMessageHandler s_upstreamMessageHandler; static QList s_engines; + static QtMessageHandler s_upstreamMessageHandler; + static QLoggingCategory::CategoryFilter s_oldCategoryFilter; static void logMessageHandler(QtMsgType type, const QMessageLogContext &context, const QString &message); + static void logCategoryFilter(QLoggingCategory *category); }; } diff --git a/libnymea/loggingcategories.cpp b/libnymea/loggingcategories.cpp index e34f511f..33d3d838 100644 --- a/libnymea/loggingcategories.cpp +++ b/libnymea/loggingcategories.cpp @@ -21,6 +21,9 @@ * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */ #include "loggingcategories.h" +#include +#include +#include Q_LOGGING_CATEGORY(dcApplication, "Application") Q_LOGGING_CATEGORY(dcPluginMetadata, "PluginMetadata") @@ -61,3 +64,92 @@ Q_LOGGING_CATEGORY(dcBluetoothServer, "BluetoothServer") Q_LOGGING_CATEGORY(dcBluetoothServerTraffic, "BluetoothServerTraffic") Q_LOGGING_CATEGORY(dcMqtt, "Mqtt") Q_LOGGING_CATEGORY(dcTranslations, "Translations") + + +static QFile s_logFile; +static bool s_useColors; +static QList s_handlers; + +static const char *const normal = "\033[0m"; +static const char *const warning = "\033[33m"; +static const char *const error = "\033[31m"; + +void nymeaInstallMessageHandler(QtMessageHandler handler) +{ + s_handlers.append(handler); +} + +void nymeaUninstallMessageHandler(QtMessageHandler handler) +{ + s_handlers.removeAll(handler); +} + +void nymeaLogMessageHandler(QtMsgType type, const QMessageLogContext &context, const QString &message) +{ + // Copy message to all installed nymea handlers + foreach (QtMessageHandler handler, s_handlers) { + handler(type, context, message); + } + + QString messageString; + QString timeString = QDateTime::currentDateTime().toString("yyyy.MM.dd hh:mm:ss.zzz"); + switch (type) { +#if (QT_VERSION >= QT_VERSION_CHECK(5, 5, 0)) + case QtInfoMsg: + messageString = QString(" I %1 | %2: %3").arg(timeString).arg(context.category).arg(message); + fprintf(stdout, " I | %s: %s\n", context.category, message.toUtf8().data()); + break; +#endif + case QtDebugMsg: + messageString = QString(" I %1 | %2: %3").arg(timeString).arg(context.category).arg(message); + fprintf(stdout, " I | %s: %s\n", context.category, message.toUtf8().data()); + break; + case QtWarningMsg: + messageString = QString(" W %1 | %2: %3").arg(timeString).arg(context.category).arg(message); + fprintf(stdout, "%s W | %s: %s%s\n", s_useColors ? warning : "", context.category, message.toUtf8().data(), s_useColors ? normal : ""); + break; + case QtCriticalMsg: + messageString = QString(" C %1 | %2: %3").arg(timeString).arg(context.category).arg(message); + fprintf(stdout, "%s C | %s: %s%s\n", s_useColors ? error : "", context.category, message.toUtf8().data(), s_useColors ? error : ""); + break; + case QtFatalMsg: + messageString = QString(" F %1 | %2: %3").arg(timeString).arg(context.category).arg(message); + fprintf(stdout, "%s F | %s: %s%s\n", s_useColors ? error : "", context.category, message.toUtf8().data(), s_useColors ? error: ""); + break; + } + fflush(stdout); + + if (s_logFile.isOpen()) { + QTextStream textStream(&s_logFile); + textStream << messageString << endl; + } +} + +bool initLogging(const QString &fileName, bool useColors) +{ + s_useColors = useColors; + + qInstallMessageHandler(nymeaLogMessageHandler); + + if (!fileName.isEmpty()) { + QFileInfo fi(fileName); + QDir dir(fi.absolutePath()); + if (!dir.exists() && !dir.mkpath(dir.absolutePath())) { + qWarning() << "Error logfile path:" << fileName; + return false; + } + s_logFile.setFileName(fileName); + if (!s_logFile.open(QFile::WriteOnly | QFile::Append)) { + qWarning() << "Error opening log file:" <= QT_VERSION_CHECK(5, 5, 0)) - case QtInfoMsg: - messageString = QString(" I %1 | %2: %3").arg(timeString).arg(context.category).arg(message); - fprintf(stdout, " I | %s: %s\n", context.category, message.toUtf8().data()); - break; -#endif - case QtDebugMsg: - messageString = QString(" I %1 | %2: %3").arg(timeString).arg(context.category).arg(message); - fprintf(stdout, " I | %s: %s\n", context.category, message.toUtf8().data()); - break; - case QtWarningMsg: - messageString = QString(" W %1 | %2: %3").arg(timeString).arg(context.category).arg(message); - fprintf(stdout, "%s W | %s: %s%s\n", warning, context.category, message.toUtf8().data(), normal); - break; - case QtCriticalMsg: - messageString = QString(" C %1 | %2: %3").arg(timeString).arg(context.category).arg(message); - fprintf(stdout, "%s C | %s: %s%s\n", error, context.category, message.toUtf8().data(), normal); - break; - case QtFatalMsg: - messageString = QString(" F %1 | %2: %3").arg(timeString).arg(context.category).arg(message); - fprintf(stdout, "%s F | %s: %s%s\n", error, context.category, message.toUtf8().data(), normal); - break; - } - fflush(stdout); - - if (s_logFile.isOpen()) { - QTextStream textStream(&s_logFile); - textStream << messageString << endl; - } -} int main(int argc, char *argv[]) { - qInstallMessageHandler(consoleLogHandler); - NymeaApplication application(argc, argv); application.setOrganizationName("nymea"); application.setApplicationName("nymead"); @@ -145,9 +103,12 @@ int main(int argc, char *argv[]) QCommandLineOption allOption(QStringList() << "p" << "print-all", QCoreApplication::translate("nymea", "Enables all debug categories except *Traffic and *Debug categories. Single debug categories can be disabled again with -d parameter.")); parser.addOption(allOption); - QCommandLineOption logOption({"l", "log"}, QCoreApplication::translate("nymea", "Specify a log file to write to, if this option is not specified, logs will be printed to the standard output."), "logfile", "/var/log/nymead.log"); + QCommandLineOption logOption({"l", "log"}, QCoreApplication::translate("nymea", "Specify a log file to write to, if this option is not specified, logs will be printed to the standard output."), "logfile"); parser.addOption(logOption); + QCommandLineOption noColorOption({"c", "no-colors"}, QCoreApplication::translate("nymea", "Log output is colorized by default. Use this option to disable colors.")); + parser.addOption(noColorOption); + QCommandLineOption dbusOption(QStringList() << "session", QCoreApplication::translate("nymea", "If specified, all D-Bus interfaces will be bound to the session bus instead of the system bus.")); parser.addOption(dbusOption); @@ -157,21 +118,11 @@ int main(int argc, char *argv[]) parser.process(application); // Open the logfile, if any specified - if (parser.isSet(logOption)) { - QFileInfo fi(parser.value(logOption)); - QDir dir(fi.absolutePath()); - if (!dir.exists() && !dir.mkpath(dir.absolutePath())) { - qWarning() << "Error opening log file" << parser.value(logOption); - return 1; - } - s_logFile.setFileName(parser.value(logOption)); - if (!s_logFile.open(QFile::WriteOnly | QFile::Append)) { - qWarning() << "Error opening log file" << parser.value(logOption); - return 1; - } + if (!initLogging(parser.value(logOption), !parser.isSet(noColorOption))) { + qWarning() << "Error opening log file" << parser.value(logOption); + return 1; } - /* The logging rules will be evaluated sequentially * 1. All debug categories off * 2. Enable all debug categories if requested from command line (-p) @@ -215,9 +166,6 @@ int main(int argc, char *argv[]) // } } - // Always enable the "qml" category. It's needed for the scriptengine to snoop in on console messages. - loggingRules.append("qml.debug=true"); - // Finally set the rules for the logging QLoggingCategory::setFilterRules(loggingRules.join('\n')); @@ -259,16 +207,12 @@ int main(int argc, char *argv[]) // create core instance NymeaCore::instance()->init(); int ret = application.exec(); - if (s_logFile.isOpen()) { - s_logFile.close(); - } + closeLogFile(); return ret; } NymeaService service(argc, argv); int ret = service.exec(); - if (s_logFile.isOpen()) { - s_logFile.close(); - } + closeLogFile(); return ret; } diff --git a/tests/auto/jsonrpc/testjsonrpc.cpp b/tests/auto/jsonrpc/testjsonrpc.cpp index d783e15f..db15daf2 100644 --- a/tests/auto/jsonrpc/testjsonrpc.cpp +++ b/tests/auto/jsonrpc/testjsonrpc.cpp @@ -665,7 +665,7 @@ void TestJSONRPC::enableDisableNotifications_legacy() QStringList expectedNamespaces; if (enabled == "true") { - expectedNamespaces << "Actions" << "NetworkManager" << "Devices" << "System" << "Rules" << "States" << "Logging" << "Tags" << "JSONRPC" << "Configuration" << "Events"; + expectedNamespaces << "Actions" << "NetworkManager" << "Devices" << "System" << "Rules" << "States" << "Logging" << "Tags" << "JSONRPC" << "Configuration" << "Events" << "Scripts"; } std::sort(expectedNamespaces.begin(), expectedNamespaces.end());