diff --git a/src/util/logging.cpp b/src/util/logging.cpp index c967947789f..0fbbe871cf6 100644 --- a/src/util/logging.cpp +++ b/src/util/logging.cpp @@ -19,9 +19,12 @@ 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. QFile s_logfile; @@ -29,6 +32,10 @@ QFile s_logfile; // Whether to break on debug assertions. bool s_debugAssertBreak = false; +const QString kThreadNamePattern = QStringLiteral("{{threadname}}"); +const QString kDefaultMessagePattern = QStringLiteral("%{type} [") + + kThreadNamePattern + QStringLiteral("] %{message}"); + const QLoggingCategory kDefaultLoggingCategory = QLoggingCategory(nullptr); enum class WriteFlag { @@ -43,41 +50,109 @@ 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 logfiles should have a fixed format). +inline QString formatLogFileMessage( + QtMsgType type, + const QString& message, + const QString& threadName) { + 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 QString& message, + const QString& threadName, + bool flush) { + QString formattedMessageStr = + formatLogFileMessage(type, 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(kThreadNamePattern, threadName) + .toLocal8Bit(); + + QMutexLocker locked(&s_mutexStdErr); + 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()) { + QTextStream textStream(&threadName); + textStream << QThread::currentThread(); + } + + const bool flush = flags & WriteFlag::Flush; if (flags & WriteFlag::StdErr) { - const int written = fwrite( - message.constData(), sizeof(char), message.size(), stderr); - Q_UNUSED(written); - DEBUG_ASSERT(written == message.size()); - if (flags & WriteFlag::Flush) { - // Flushing stderr might not be necessary, because message - // should end with a newline character. Flushing occcurs - // 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, message, threadName, flush); } } @@ -93,7 +168,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 +175,6 @@ void handleMessage( switch (type) { case QtDebugMsg: levelName = "Debug"; - baSize += strlen(levelName); isControllerDebug = input.startsWith(QLatin1String( ControllerDebug::kLogMessagePrefix)); @@ -121,7 +194,6 @@ void handleMessage( break; case QtInfoMsg: levelName = "Info"; - baSize += strlen(levelName); if (Logging::enabled(LogLevel::Info)) { writeFlags |= WriteFlag::StdErr; } @@ -133,7 +205,6 @@ void handleMessage( break; case QtWarningMsg: levelName = "Warning"; - baSize += strlen(levelName); if (Logging::enabled(LogLevel::Warning)) { writeFlags |= WriteFlag::StdErr; } @@ -145,13 +216,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 +232,9 @@ void handleMessage( return; } - QByteArray threadName = - QThread::currentThread()->objectName().toLocal8Bit(); - if (threadName.isEmpty()) { - QTextStream textStream(&threadName); - textStream << QThread::currentThread(); - } - 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); - if (isDebugAssert) { if (s_debugAssertBreak) { - writeToLog(ba, WriteFlag::All); + writeToLog(type, context, input, WriteFlag::All); raise(SIGINT); // When the debugger returns, continue normally. return; @@ -226,12 +244,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", input.toLocal8Bit().constData()); return; #endif // MIXXX_DEBUG_ASSERTIONS_FATAL } - writeToLog(ba, writeFlags); + writeToLog(type, context, input, writeFlags); } } // anonymous namespace @@ -291,6 +309,10 @@ void Logging::initialize( s_debugAssertBreak = debugAssertBreak; + if (qgetenv("QT_MESSAGE_PATTERN").isEmpty()) { + qSetMessagePattern(kDefaultMessagePattern); + } + // Install the Qt message handler. qInstallMessageHandler(handleMessage);