fix logging system to cope with the qml output redirection

pull/231/head
Michael Zanetti 2019-11-28 12:09:50 +01:00
parent bffdf9cb88
commit 5a36c2347f
8 changed files with 189 additions and 88 deletions

View File

@ -41,7 +41,6 @@
namespace nymeaserver {
QtMessageHandler DebugServerHandler::s_oldLogMessageHandler = nullptr;
QList<QWebSocket*> 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);
}
}

View File

@ -41,7 +41,6 @@ public:
HttpReply *processDebugRequest(const QString &requestPath, const QUrlQuery &requestQuery);
private:
static QtMessageHandler s_oldLogMessageHandler;
static QList<QWebSocket*> s_websocketClients;
static void logMessageHandler(QtMsgType type, const QMessageLogContext &context, const QString &message);

View File

@ -39,23 +39,43 @@
namespace nymeaserver {
QtMessageHandler ScriptEngine::s_upstreamMessageHandler;
QList<ScriptEngine*> 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<ScriptEvent>("nymea", 1, 0, "DeviceEvent");
qmlRegisterType<ScriptAction>("nymea", 1, 0, "DeviceAction");
qmlRegisterType<ScriptState>("nymea", 1, 0, "DeviceState");
m_engine = new QQmlEngine(this);
m_engine->setProperty("deviceManager", reinterpret_cast<quint64>(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<QQmlError> &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<ScriptEvent>("nymea", 1, 0, "DeviceEvent");
qmlRegisterType<ScriptAction>("nymea", 1, 0, "DeviceAction");
qmlRegisterType<ScriptState>("nymea", 1, 0, "DeviceState");
m_engine = new QQmlApplicationEngine(this);
m_engine->setProperty("deviceManager", reinterpret_cast<quint64>(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);
}
}

View File

@ -24,6 +24,8 @@
#include <QObject>
#include <QUuid>
#include <QQmlEngine>
#include <QJsonValue>
#include <QLoggingCategory>
#include "devices/devicemanager.h"
#include "script.h"
@ -94,9 +96,11 @@ private:
QHash<QUuid, Script*> m_scripts;
static QtMessageHandler s_upstreamMessageHandler;
static QList<ScriptEngine*> 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);
};
}

View File

@ -21,6 +21,9 @@
* * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * */
#include "loggingcategories.h"
#include <QFileInfo>
#include <QDir>
#include <QDateTime>
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<QtMessageHandler> 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:" <<fileName;
return false;
}
}
return true;
}
void closeLogFile()
{
if (s_logFile.isOpen()) {
s_logFile.close();
}
}

View File

@ -68,4 +68,23 @@ Q_DECLARE_LOGGING_CATEGORY(dcMqtt)
Q_DECLARE_LOGGING_CATEGORY(dcTranslations)
Q_DECLARE_LOGGING_CATEGORY(dcCoap)
/*
Installs a nymea log message handler in the system.
This is different to the qLogMessageHandler which works like a chain.
In nymea we have the use case that we need to copy log messages
to different places and also dynamically install/uninstall such
handlers.
If you need to copy log messages, use this, if you need to modify log messages
for the entire system (e.g. redirect to a different logging category, the Qt's
mechanism of qInstallMessageHandler() is still available and will always be called
*before* distributing the message to every nymea message handler.
*/
void nymeaInstallMessageHandler(QtMessageHandler handler);
void nymeaUninstallMessageHandler(QtMessageHandler handler);
bool initLogging(const QString &fileName, bool useColors);
void closeLogFile();
#endif // LOGGINGCATEGORYS_H

View File

@ -44,54 +44,12 @@
#include "nymeaapplication.h"
#include "loggingcategories.h"
static QFile s_logFile;
static const char *const normal = "\033[0m";
static const char *const warning = "\e[33m";
static const char *const error = "\e[31m";
using namespace nymeaserver;
static void consoleLogHandler(QtMsgType type, const QMessageLogContext& context, const QString& 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", 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;
}

View File

@ -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());