From 023058c498ad1710351298f8bec02276806f6af0 Mon Sep 17 00:00:00 2001 From: Jan Holthuis Date: Thu, 22 Oct 2020 23:06:41 +0200 Subject: logging: Add support for QT_MESSAGE_PATTERN env var --- src/util/logging.cpp | 76 +++++++++++----------------------------------------- 1 file changed, 16 insertions(+), 60 deletions(-) diff --git a/src/util/logging.cpp b/src/util/logging.cpp index c967947789..86f19cd29f 100644 --- a/src/util/logging.cpp +++ b/src/util/logging.cpp @@ -50,13 +50,13 @@ inline void writeToLog( DEBUG_ASSERT(!message.isEmpty()); DEBUG_ASSERT(flags & (WriteFlag::StdErr | WriteFlag::File)); if (flags & WriteFlag::StdErr) { - const int written = fwrite( + const size_t written = fwrite( message.constData(), sizeof(char), message.size(), stderr); Q_UNUSED(written); - DEBUG_ASSERT(written == message.size()); + DEBUG_ASSERT(written == static_cast(message.size())); if (flags & WriteFlag::Flush) { // Flushing stderr might not be necessary, because message - // should end with a newline character. Flushing occcurs + // should end with a newline character. Flushing occurs // only infrequently (log level >= Critical), so better safe // than sorry. const int ret = fflush(stderr); @@ -93,7 +93,6 @@ void handleMessage( QtMsgType type, const QMessageLogContext& context, const QString& input) { - int baSize = 2 + 3 + 1; // all separators + newline (see below) const char* levelName = nullptr; WriteFlags writeFlags = WriteFlag::None; bool isDebugAssert = false; @@ -101,7 +100,6 @@ void handleMessage( switch (type) { case QtDebugMsg: levelName = "Debug"; - baSize += strlen(levelName); isControllerDebug = input.startsWith(QLatin1String( ControllerDebug::kLogMessagePrefix)); @@ -121,7 +119,6 @@ void handleMessage( break; case QtInfoMsg: levelName = "Info"; - baSize += strlen(levelName); if (Logging::enabled(LogLevel::Info)) { writeFlags |= WriteFlag::StdErr; } @@ -133,7 +130,6 @@ void handleMessage( break; case QtWarningMsg: levelName = "Warning"; - baSize += strlen(levelName); if (Logging::enabled(LogLevel::Warning)) { writeFlags |= WriteFlag::StdErr; } @@ -145,13 +141,11 @@ void handleMessage( break; case QtCriticalMsg: levelName = "Critical"; - baSize += strlen(levelName); writeFlags = WriteFlag::All; isDebugAssert = input.startsWith(QLatin1String(kDebugAssertPrefix)); break; case QtFatalMsg: levelName = "Fatal"; - baSize += strlen(levelName); writeFlags = WriteFlag::All; break; } @@ -163,60 +157,16 @@ void handleMessage( return; } - QByteArray threadName = - QThread::currentThread()->objectName().toLocal8Bit(); + QString threadName = QThread::currentThread()->objectName(); if (threadName.isEmpty()) { - QTextStream textStream(&threadName); - textStream << QThread::currentThread(); + threadName = QStringLiteral("%{qthreadptr}"); } - baSize += threadName.size(); - - QByteArray input8Bit; - if (isControllerDebug) { - input8Bit = input.mid(strlen(ControllerDebug::kLogMessagePrefix) + 1).toLocal8Bit(); - } else { - input8Bit = input.toLocal8Bit(); - } - baSize += input8Bit.size(); - - const char* categoryName = context.category; - int categoryName_len = 0; - if (categoryName) { - categoryName_len = strlen(categoryName); - if (categoryName_len > 0) { - if (strcmp(categoryName, kDefaultLoggingCategory.categoryName()) != 0) { - baSize += 1; // additional separator (see below) - baSize += categoryName_len; - } else { - // Suppress default category name - categoryName = nullptr; - categoryName_len = 0; - } - } - } - - QByteArray ba; - ba.reserve(baSize); - - ba.append(levelName); - ba.append(" ["); - ba.append(threadName, threadName.size()); - if (categoryName) { - ba.append("] "); - ba.append(categoryName, categoryName_len); - ba.append(": "); - } else { - ba.append("]: "); - } - ba.append(input8Bit, input8Bit.size()); - ba.append('\n'); - - // Verify that the reserved size matches the actual size - DEBUG_ASSERT(ba.size() == baSize); + QString logMessage = qFormatLogMessage(type, context, input) + QChar('\n'); + const QByteArray array = logMessage.replace("{{threadname}}", threadName).toLocal8Bit(); if (isDebugAssert) { if (s_debugAssertBreak) { - writeToLog(ba, WriteFlag::All); + writeToLog(array, WriteFlag::All); raise(SIGINT); // When the debugger returns, continue normally. return; @@ -226,12 +176,12 @@ void handleMessage( #ifdef MIXXX_DEBUG_ASSERTIONS_FATAL // re-send as fatal. // The "%s" is intentional. See -Werror=format-security. - qFatal("%s", input8Bit.constData()); + qFatal("%s", array.constData()); return; #endif // MIXXX_DEBUG_ASSERTIONS_FATAL } - writeToLog(ba, writeFlags); + writeToLog(array, writeFlags); } } // anonymous namespace @@ -291,6 +241,12 @@ void Logging::initialize( s_debugAssertBreak = debugAssertBreak; + // Set the default message pattern if the QT_MESSAGE_PATTERN variable is + // not set. + if (qgetenv("QT_MESSAGE_PATTERN").isEmpty()) { + qSetMessagePattern("%{type} [{{threadname}}] %{message}"); + } + // Install the Qt message handler. qInstallMessageHandler(handleMessage); -- cgit v1.2.3 From f8810d0377cc8fc775a3a9ecffa09440eaf860bf Mon Sep 17 00:00:00 2001 From: Jan Holthuis Date: Fri, 23 Oct 2020 11:17:30 +0200 Subject: logging: Ensure a fixed format for log files --- src/util/logging.cpp | 138 +++++++++++++++++++++++++++++++++++++-------------- 1 file changed, 100 insertions(+), 38 deletions(-) diff --git a/src/util/logging.cpp b/src/util/logging.cpp index 86f19cd29f..496c64f7b8 100644 --- a/src/util/logging.cpp +++ b/src/util/logging.cpp @@ -43,41 +43,110 @@ Q_DECLARE_FLAGS(WriteFlags, WriteFlag) Q_DECLARE_OPERATORS_FOR_FLAGS(WriteFlags) -// Handles actually writing to stderr and the log file. +/// Format message for writing into log file (ignores QT_MESSAGE_PATTERN, +/// because out logfiles should have a fixed format). +inline QString formatLogFileMessage( + QtMsgType type, + const QMessageLogContext& context, + const QString& message, + const QString& threadName) { + Q_UNUSED(context); + + QString levelName; + switch (type) { + case QtDebugMsg: + levelName = QStringLiteral("Debug"); + break; + case QtInfoMsg: + levelName = QStringLiteral("Info"); + break; + case QtWarningMsg: + levelName = QStringLiteral("Warning"); + break; + case QtCriticalMsg: + levelName = QStringLiteral("Critical"); + break; + case QtFatalMsg: + levelName = QStringLiteral("Fatal"); + break; + } + + return levelName + QStringLiteral(" [") + threadName + QStringLiteral("] ") + message; +} + +/// Actually write a log message to a file. +inline void writeToFile( + QtMsgType type, + const QMessageLogContext& context, + const QString& message, + const QString& threadName, + bool flush) { + QString formattedMessageStr = + formatLogFileMessage(type, context, message, threadName) + + QChar('\n'); + QByteArray formattedMessage = formattedMessageStr.toLocal8Bit(); + + QMutexLocker locked(&s_mutexLogfile); + // Writing to a closed QFile could cause an infinite recursive loop + // by logging to qWarning! + if (s_logfile.isOpen()) { + const int written = s_logfile.write(formattedMessage); + Q_UNUSED(written); + DEBUG_ASSERT(written == formattedMessage.size()); + if (flush) { + const bool flushed = s_logfile.flush(); + Q_UNUSED(flushed); + DEBUG_ASSERT(flushed); + } + } +} + +/// Actually write a log message to stderr. +inline void writeToStdErr( + QtMsgType type, + const QMessageLogContext& context, + const QString& message, + const QString& threadName, + bool flush) { + QString formattedMessageStr = qFormatLogMessage(type, context, message) + QChar('\n'); + const QByteArray formattedMessage = + formattedMessageStr.replace("{{threadname}}", threadName) + .toLocal8Bit(); + const size_t written = fwrite( + formattedMessage.constData(), sizeof(char), formattedMessage.size(), stderr); + Q_UNUSED(written); + DEBUG_ASSERT(written == static_cast(formattedMessage.size())); + if (flush) { + // Flushing stderr might not be necessary, because message + // should end with a newline character. Flushing occurs + // only infrequently (log level >= Critical), so better safe + // than sorry. + const int ret = fflush(stderr); + Q_UNUSED(ret); + DEBUG_ASSERT(ret == 0); + } +} + +/// Handles writing to stderr and the log file. inline void writeToLog( - const QByteArray& message, + QtMsgType type, + const QMessageLogContext& context, + const QString& message, WriteFlags flags) { DEBUG_ASSERT(!message.isEmpty()); DEBUG_ASSERT(flags & (WriteFlag::StdErr | WriteFlag::File)); + + QString threadName = QThread::currentThread()->objectName(); + if (threadName.isEmpty()) { + threadName = QStringLiteral("%{qthreadptr}"); + } + + const bool flush = flags & WriteFlag::Flush; if (flags & WriteFlag::StdErr) { - const size_t written = fwrite( - message.constData(), sizeof(char), message.size(), stderr); - Q_UNUSED(written); - DEBUG_ASSERT(written == static_cast(message.size())); - if (flags & WriteFlag::Flush) { - // Flushing stderr might not be necessary, because message - // should end with a newline character. Flushing occurs - // only infrequently (log level >= Critical), so better safe - // than sorry. - const int ret = fflush(stderr); - Q_UNUSED(ret); - DEBUG_ASSERT(ret == 0); - } + writeToStdErr(type, context, message, threadName, flush); } if (flags & WriteFlag::File) { - QMutexLocker locked(&s_mutexLogfile); - // Writing to a closed QFile could cause an infinite recursive loop - // by logging to qWarning! - if (s_logfile.isOpen()) { - const int written = s_logfile.write(message); - Q_UNUSED(written); - DEBUG_ASSERT(written == message.size()); - if (flags & WriteFlag::Flush) { - const bool flushed = s_logfile.flush(); - Q_UNUSED(flushed); - DEBUG_ASSERT(flushed); - } - } + writeToFile(type, context, message, threadName, flush); } } @@ -157,16 +226,9 @@ void handleMessage( return; } - QString threadName = QThread::currentThread()->objectName(); - if (threadName.isEmpty()) { - threadName = QStringLiteral("%{qthreadptr}"); - } - QString logMessage = qFormatLogMessage(type, context, input) + QChar('\n'); - const QByteArray array = logMessage.replace("{{threadname}}", threadName).toLocal8Bit(); - if (isDebugAssert) { if (s_debugAssertBreak) { - writeToLog(array, WriteFlag::All); + writeToLog(type, context, input, WriteFlag::All); raise(SIGINT); // When the debugger returns, continue normally. return; @@ -176,12 +238,12 @@ void handleMessage( #ifdef MIXXX_DEBUG_ASSERTIONS_FATAL // re-send as fatal. // The "%s" is intentional. See -Werror=format-security. - qFatal("%s", array.constData()); + qFatal("%s", input.toLocal8Bit().constData()); return; #endif // MIXXX_DEBUG_ASSERTIONS_FATAL } - writeToLog(array, writeFlags); + writeToLog(type, context, input, writeFlags); } } // anonymous namespace -- cgit v1.2.3 From df034bd217719f1405566c97c559954f2c324307 Mon Sep 17 00:00:00 2001 From: Jan Holthuis Date: Fri, 23 Oct 2020 12:23:41 +0200 Subject: logging: Add mutex for writing to stderr --- src/util/logging.cpp | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/util/logging.cpp b/src/util/logging.cpp index 496c64f7b8..514cf22687 100644 --- a/src/util/logging.cpp +++ b/src/util/logging.cpp @@ -21,6 +21,7 @@ namespace { // Mutex guarding s_logfile. QMutex s_mutexLogfile; +QMutex s_mutexStdErr; // The file handle for Mixxx's log file. QFile s_logfile; @@ -112,6 +113,8 @@ inline void writeToStdErr( const QByteArray formattedMessage = formattedMessageStr.replace("{{threadname}}", threadName) .toLocal8Bit(); + + QMutexLocker locked(&s_mutexStdErr); const size_t written = fwrite( formattedMessage.constData(), sizeof(char), formattedMessage.size(), stderr); Q_UNUSED(written); -- cgit v1.2.3 From 938c96281c904a9f8813c0f5af4acf76d4c84daa Mon Sep 17 00:00:00 2001 From: Jan Holthuis Date: Fri, 23 Oct 2020 13:48:42 +0200 Subject: logging: Fix handling of threadname in pattern --- src/util/logging.cpp | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/src/util/logging.cpp b/src/util/logging.cpp index 514cf22687..e82c2715ab 100644 --- a/src/util/logging.cpp +++ b/src/util/logging.cpp @@ -30,6 +30,8 @@ QFile s_logfile; // Whether to break on debug assertions. bool s_debugAssertBreak = false; +const QString kThreadNamePattern = QStringLiteral("{{threadname}}"); + const QLoggingCategory kDefaultLoggingCategory = QLoggingCategory(nullptr); enum class WriteFlag { @@ -111,7 +113,7 @@ inline void writeToStdErr( bool flush) { QString formattedMessageStr = qFormatLogMessage(type, context, message) + QChar('\n'); const QByteArray formattedMessage = - formattedMessageStr.replace("{{threadname}}", threadName) + formattedMessageStr.replace(kThreadNamePattern, threadName) .toLocal8Bit(); QMutexLocker locked(&s_mutexStdErr); @@ -141,7 +143,9 @@ inline void writeToLog( QString threadName = QThread::currentThread()->objectName(); if (threadName.isEmpty()) { - threadName = QStringLiteral("%{qthreadptr}"); + threadName = QStringLiteral("0x") + + QString::number( + reinterpret_cast(QThread::currentThread()), 16); } const bool flush = flags & WriteFlag::Flush; @@ -309,7 +313,8 @@ void Logging::initialize( // Set the default message pattern if the QT_MESSAGE_PATTERN variable is // not set. if (qgetenv("QT_MESSAGE_PATTERN").isEmpty()) { - qSetMessagePattern("%{type} [{{threadname}}] %{message}"); + qSetMessagePattern(QStringLiteral("%{type} [") + kThreadNamePattern + + QStringLiteral("] %{message}")); } // Install the Qt message handler. -- cgit v1.2.3 From 50195a472ff5ef32ce6cca93df599b9952c98ded Mon Sep 17 00:00:00 2001 From: Jan Holthuis Date: Fri, 23 Oct 2020 19:06:47 +0200 Subject: logging: Fix some minor style issues and improve thread ptr handling --- src/util/logging.cpp | 18 ++++++++---------- 1 file changed, 8 insertions(+), 10 deletions(-) diff --git a/src/util/logging.cpp b/src/util/logging.cpp index e82c2715ab..438934ba2a 100644 --- a/src/util/logging.cpp +++ b/src/util/logging.cpp @@ -19,8 +19,10 @@ namespace { -// Mutex guarding s_logfile. +/// Mutex guarding s_logfile. QMutex s_mutexLogfile; + +/// Mutex guarding stderr. QMutex s_mutexStdErr; // The file handle for Mixxx's log file. @@ -47,13 +49,11 @@ Q_DECLARE_FLAGS(WriteFlags, WriteFlag) Q_DECLARE_OPERATORS_FOR_FLAGS(WriteFlags) /// Format message for writing into log file (ignores QT_MESSAGE_PATTERN, -/// because out logfiles should have a fixed format). +/// because logfiles should have a fixed format). inline QString formatLogFileMessage( QtMsgType type, - const QMessageLogContext& context, const QString& message, const QString& threadName) { - Q_UNUSED(context); QString levelName; switch (type) { @@ -80,12 +80,11 @@ inline QString formatLogFileMessage( /// Actually write a log message to a file. inline void writeToFile( QtMsgType type, - const QMessageLogContext& context, const QString& message, const QString& threadName, bool flush) { QString formattedMessageStr = - formatLogFileMessage(type, context, message, threadName) + + formatLogFileMessage(type, message, threadName) + QChar('\n'); QByteArray formattedMessage = formattedMessageStr.toLocal8Bit(); @@ -143,9 +142,8 @@ inline void writeToLog( QString threadName = QThread::currentThread()->objectName(); if (threadName.isEmpty()) { - threadName = QStringLiteral("0x") + - QString::number( - reinterpret_cast(QThread::currentThread()), 16); + QTextStream textStream(&threadName); + textStream << QThread::currentThread(); } const bool flush = flags & WriteFlag::Flush; @@ -153,7 +151,7 @@ inline void writeToLog( writeToStdErr(type, context, message, threadName, flush); } if (flags & WriteFlag::File) { - writeToFile(type, context, message, threadName, flush); + writeToFile(type, message, threadName, flush); } } -- cgit v1.2.3 From 7640a26ac892892539e8bf931fbb7ed6c3c581c4 Mon Sep 17 00:00:00 2001 From: Jan Holthuis Date: Fri, 23 Oct 2020 20:57:02 +0200 Subject: logging: Use a global constant for default message pattern --- src/util/logging.cpp | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/src/util/logging.cpp b/src/util/logging.cpp index 438934ba2a..1852728d81 100644 --- a/src/util/logging.cpp +++ b/src/util/logging.cpp @@ -33,6 +33,8 @@ QFile s_logfile; bool s_debugAssertBreak = false; const QString kThreadNamePattern = QStringLiteral("{{threadname}}"); +const QString kDefaultMessagePattern = QStringLiteral("%{type} [") + + kThreadNamePattern + QStringLiteral("] %{message}"); const QLoggingCategory kDefaultLoggingCategory = QLoggingCategory(nullptr); @@ -308,11 +310,8 @@ void Logging::initialize( s_debugAssertBreak = debugAssertBreak; - // Set the default message pattern if the QT_MESSAGE_PATTERN variable is - // not set. if (qgetenv("QT_MESSAGE_PATTERN").isEmpty()) { - qSetMessagePattern(QStringLiteral("%{type} [") + kThreadNamePattern + - QStringLiteral("] %{message}")); + qSetMessagePattern(kDefaultMessagePattern); } // Install the Qt message handler. -- cgit v1.2.3 From f38755e28367bd3d4c913ea27f76b882e307b75b Mon Sep 17 00:00:00 2001 From: Jan Holthuis Date: Fri, 23 Oct 2020 23:23:34 +0200 Subject: logging: Remove stray empty line --- src/util/logging.cpp | 1 - 1 file changed, 1 deletion(-) diff --git a/src/util/logging.cpp b/src/util/logging.cpp index 1852728d81..0fbbe871cf 100644 --- a/src/util/logging.cpp +++ b/src/util/logging.cpp @@ -56,7 +56,6 @@ inline QString formatLogFileMessage( QtMsgType type, const QString& message, const QString& threadName) { - QString levelName; switch (type) { case QtDebugMsg: -- cgit v1.2.3