Merge pull request #2745 from uklotzde/logging

Logging Pt. 1: Prepare for QLoggingCategory

4 files changed, 250 insertions, 171 deletions

diff --git a/src/util/cmdlineargs.cpp b/src/util/cmdlineargs.cpp
index 61e75afbe3..8b040b58b1 100644
--- a/src/util/cmdlineargs.cpp
+++ b/src/util/cmdlineargs.cpp
@@ -27,6 +27,27 @@ CmdlineArgs::CmdlineArgs()
 #endif
 }
 
+namespace {
+    bool parseLogLevel(
+        QLatin1String logLevel,
+        mixxx::LogLevel *pLogLevel) {
+        if (logLevel == QLatin1String("trace")) {
+            *pLogLevel = mixxx::LogLevel::Trace;
+        } else if (logLevel == QLatin1String("debug")) {
+            *pLogLevel = mixxx::LogLevel::Debug;
+        } else if (logLevel == QLatin1String("info")) {
+            *pLogLevel = mixxx::LogLevel::Info;
+        } else if (logLevel == QLatin1String("warning")) {
+            *pLogLevel = mixxx::LogLevel::Warning;
+        } else if (logLevel == QLatin1String("critical")) {
+            *pLogLevel = mixxx::LogLevel::Critical;
+        } else {
+            return false;
+        }
+        return true;
+    }
+}
+
 bool CmdlineArgs::Parse(int &argc, char **argv) {
     bool logLevelSet = false;
     for (int i = 0; i < argc; ++i) {
@@ -61,34 +82,14 @@ bool CmdlineArgs::Parse(int &argc, char **argv) {
         } else if (argv[i] == QString("--logLevel") && i+1 < argc) {
             logLevelSet = true;
             auto level = QLatin1String(argv[i+1]);
-            if (level == "trace") {
-                m_logLevel = mixxx::LogLevel::Trace;
-            } else if (level == "debug") {
-                m_logLevel = mixxx::LogLevel::Debug;
-            } else if (level == "info") {
-                m_logLevel = mixxx::LogLevel::Info;
-            } else if (level == "warning") {
-                m_logLevel = mixxx::LogLevel::Warning;
-            } else if (level == "critical") {
-                m_logLevel = mixxx::LogLevel::Critical;
-            } else {
+            if (!parseLogLevel(level, &m_logLevel)) {
                 fputs("\nlogLevel argument wasn't 'trace', 'debug', 'info', 'warning', or 'critical'! Mixxx will only output\n\
 warnings and errors to the console unless this is set properly.\n", stdout);
             }
             i++;
         } else if (argv[i] == QString("--logFlushLevel") && i+1 < argc) {
             auto level = QLatin1String(argv[i+1]);
-            if (level == "trace") {
-                m_logFlushLevel = mixxx::LogLevel::Trace;
-            } else if (level == "debug") {
-                m_logFlushLevel = mixxx::LogLevel::Debug;
-            } else if (level == "info") {
-                m_logFlushLevel = mixxx::LogLevel::Info;
-            } else if (level == "warning") {
-                m_logFlushLevel = mixxx::LogLevel::Warning;
-            } else if (level == "critical") {
-                m_logFlushLevel = mixxx::LogLevel::Critical;
-            } else {
+            if (!parseLogLevel(level, &m_logFlushLevel)) {
                 fputs("\nlogFushLevel argument wasn't 'trace', 'debug', 'info', 'warning', or 'critical'! Mixxx will only flush messages to mixxx.log\n\
 when a critical error occurs unless this is set properly.\n", stdout);
             }
diff --git a/src/util/logger.h b/src/util/logger.h
index a99599ebda..b6c09641f2 100644
--- a/src/util/logger.h
+++ b/src/util/logger.h
@@ -28,7 +28,7 @@ public:
     }
 
     bool traceEnabled() const {
-        return Logging::traceEnabled();
+        return Logging::enabled(LogLevel::Trace);
     }
 
     // Trace the elapsed time of some timed action in microseconds.
@@ -51,7 +51,7 @@ public:
     }
 
     bool debugEnabled() const {
-        return Logging::debugEnabled();
+        return Logging::enabled(LogLevel::Debug);
     }
 
     QDebug info() const {
@@ -59,7 +59,7 @@ public:
     }
 
     bool infoEnabled() const {
-        return Logging::infoEnabled();
+        return Logging::enabled(LogLevel::Info);
     }
 
     QDebug warning() const {
diff --git a/src/util/logging.cpp b/src/util/logging.cpp
index 9e29712cf7..42112b33ba 100644
--- a/src/util/logging.cpp
+++ b/src/util/logging.cpp
@@ -1,112 +1,167 @@
 #include "util/logging.h"
 
-#include <stdio.h>
 #include <signal.h>
+#include <stdio.h>
 
 #include <QByteArray>
-#include <QDir>
 #include <QFile>
 #include <QFileInfo>
 #include <QIODevice>
+#include <QLoggingCategory>
 #include <QMutex>
 #include <QMutexLocker>
 #include <QString>
+#include <QTextStream>
 #include <QThread>
-#include <QtDebug>
-#include <QtGlobal>
-#include <QLoggingCategory>
 
 #include "controllers/controllerdebug.h"
 #include "util/assert.h"
 
-namespace mixxx {
-
-// Initialize the log level with the default value
-LogLevel g_logLevel = kLogLevelDefault;
-LogLevel g_logFlushLevel = kLogFlushLevelDefault;
-
 namespace {
 
-// Mutex guarding g_logfile.
-QMutex g_mutexLogfile;
+// Mutex guarding s_logfile.
+QMutex s_mutexLogfile;
+
 // The file handle for Mixxx's log file.
-QFile g_logfile;
+QFile s_logfile;
+
 // The log level.
 // Whether to break on debug assertions.
-bool g_debugAssertBreak = false;
+bool s_debugAssertBreak = false;
 
-// Handles actually writing to stderr and the log.
-inline void writeToLog(const QByteArray& message, bool shouldPrint,
-                       bool shouldFlush) {
-    if (shouldPrint) {
-        fwrite(message.constData(), sizeof(char), message.size(), stderr);
-    }
+const QLoggingCategory kDefaultLoggingCategory = QLoggingCategory(nullptr);
 
-    QMutexLocker locker(&g_mutexLogfile);
-    // Writing to a closed QFile can cause a recursive loop, since it prints an
-    // error using qWarning.
-    if (g_logfile.isOpen()) {
-        g_logfile.write(message);
-        if (shouldFlush) {
-            g_logfile.flush();
+enum class WriteFlag {
+    None = 0,
+    StdErr = 1 << 0,
+    File = 1 << 1,
+    Flush = 1 << 2,
+    All = StdErr | File | Flush,
+};
+
+Q_DECLARE_FLAGS(WriteFlags, WriteFlag)
+
+Q_DECLARE_OPERATORS_FOR_FLAGS(WriteFlags)
+
+// Handles actually writing to stderr and the log file.
+inline void writeToLog(
+        const QByteArray& message,
+        WriteFlags flags) {
+    DEBUG_ASSERT(!message.isEmpty());
+    DEBUG_ASSERT(flags & (WriteFlag::StdErr | WriteFlag::File));
+    if (flags & WriteFlag::StdErr) {
+        const int written = fwrite(
+                message.constData(), sizeof(char), message.size(), stderr);
+        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);
+            DEBUG_ASSERT(ret == 0);
+        }
+    }
+    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);
+            DEBUG_ASSERT(written == message.size());
+            if (flags & WriteFlag::Flush) {
+                const bool flushed = s_logfile.flush();
+                DEBUG_ASSERT(flushed);
+            }
         }
     }
 }
 
-// Debug message handler which outputs to stderr and a logfile, prepending the
-// thread name and log level.
-void MessageHandler(QtMsgType type,
-                    const QMessageLogContext&, const QString& input) {
-    // For "]: " and '\n'.
-    size_t baSize = 4;
-    const char* tag = nullptr;
-    bool shouldPrint = true;
-    bool shouldFlush = false;
+} // anonymous namespace
+
+namespace mixxx {
+
+namespace {
+
+// Debug message handler which outputs to stderr and a logfile,
+// prepending the thread name, log category, and log level.
+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;
     bool isControllerDebug = false;
     switch (type) {
-        case QtDebugMsg:
-            tag = "Debug [";
-            baSize += strlen(tag);
-            isControllerDebug = input.startsWith(QLatin1String(
-                ControllerDebug::kLogMessagePrefix));
-            shouldPrint = Logging::enabled(LogLevel::Debug) ||
-                    isControllerDebug;
-            shouldFlush = Logging::flushing(LogLevel::Debug);
-            break;
-        case QtInfoMsg:
-            tag = "Info [";
-            baSize += strlen(tag);
-            shouldPrint = Logging::enabled(LogLevel::Info);
-            shouldFlush = Logging::flushing(LogLevel::Info);
-            break;
-        case QtWarningMsg:
-            tag = "Warning [";
-            baSize += strlen(tag);
-            shouldPrint = Logging::enabled(LogLevel::Warning);
-            shouldFlush = Logging::flushing(LogLevel::Warning);
-            break;
-        case QtCriticalMsg:
-            tag = "Critical [";
-            baSize += strlen(tag);
-            shouldFlush = true;
-            isDebugAssert = input.startsWith(QLatin1String(kDebugAssertPrefix));
-            break;
-        case QtFatalMsg:
-            tag = "Fatal [";
-            baSize += strlen(tag);
-            shouldFlush = true;
-            break;
-        default:
-            tag = "Unknown [";
-            baSize += strlen(tag);
+    case QtDebugMsg:
+        levelName = "Debug";
+        baSize += strlen(levelName);
+        isControllerDebug =
+                input.startsWith(QLatin1String(
+                        ControllerDebug::kLogMessagePrefix));
+        if (isControllerDebug ||
+                Logging::enabled(LogLevel::Debug)) {
+            writeFlags |= WriteFlag::StdErr;
+            writeFlags |= WriteFlag::File;
+        }
+        if (Logging::shouldFlush(LogLevel::Debug)) {
+            writeFlags |= WriteFlag::Flush;
+        }
+        // TODO: Remove the following line.
+        // Do not write debug log messages into log file if log level
+        // Debug is not enabled starting with release 2.4.0! Until then
+        // write debug messages unconditionally into the log file
+        writeFlags |= WriteFlag::File;
+        break;
+    case QtInfoMsg:
+        levelName = "Info";
+        baSize += strlen(levelName);
+        if (Logging::enabled(LogLevel::Info)) {
+            writeFlags |= WriteFlag::StdErr;
+        }
+        if (Logging::shouldFlush(LogLevel::Info)) {
+            writeFlags |= WriteFlag::Flush;
+        }
+        // Write unconditionally into log file
+        writeFlags |= WriteFlag::File;
+        break;
+    case QtWarningMsg:
+        levelName = "Warning";
+        baSize += strlen(levelName);
+        if (Logging::enabled(LogLevel::Warning)) {
+            writeFlags |= WriteFlag::StdErr;
+        }
+        if (Logging::shouldFlush(LogLevel::Warning)) {
+            writeFlags |= WriteFlag::Flush;
+        }
+        // Write unconditionally into log file
+        writeFlags |= WriteFlag::File;
+        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;
+    }
+    VERIFY_OR_DEBUG_ASSERT(levelName) {
+        return;
     }
 
-    // qthread.cpp contains a Q_ASSERT that currentThread does not return
-    // nullptr.
-    QByteArray threadName = QThread::currentThread()
-            ->objectName().toLocal8Bit();
-    baSize += threadName.length();
+    QByteArray threadName =
+            QThread::currentThread()->objectName().toLocal8Bit();
+    if (threadName.isEmpty()) {
+        QTextStream textStream(&threadName);
+        textStream << QThread::currentThread();
+    }
+    baSize += threadName.size();
 
     QByteArray input8Bit;
     if (isControllerDebug) {
@@ -116,20 +171,43 @@ void MessageHandler(QtMsgType type,
     }
     baSize += input8Bit.size();
 
+    const char* categoryName = context.category;
+    int 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 += tag;
-    ba += threadName;
-    ba += "]: ";
-    ba += input8Bit;
-    ba += '\n';
+    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 (g_debugAssertBreak) {
-            writeToLog(ba, true, true);
+        if (s_debugAssertBreak) {
+            writeToLog(ba, WriteFlag::All);
             raise(SIGINT);
-            // If the debugger returns, continue normally.
+            // When the debugger returns, continue normally.
             return;
         }
         // If debug assertions are non-fatal, we will fall through to the normal
@@ -142,23 +220,27 @@ void MessageHandler(QtMsgType type,
 #endif // MIXXX_DEBUG_ASSERTIONS_FATAL
     }
 
-    writeToLog(ba, shouldPrint, shouldFlush);
+    writeToLog(ba, writeFlags);
 }
 
-}  // namespace
+} // anonymous namespace
+
+// Initialize the log level with the default value
+LogLevel Logging::s_logLevel = kLogLevelDefault;
+LogLevel Logging::s_logFlushLevel = kLogFlushLevelDefault;
 
 // static
 void Logging::initialize(const QDir& settingsDir,
-                         LogLevel logLevel,
-                         LogLevel logFlushLevel,
-                         bool debugAssertBreak) {
-    VERIFY_OR_DEBUG_ASSERT(!g_logfile.isOpen()) {
+        LogLevel logLevel,
+        LogLevel logFlushLevel,
+        bool debugAssertBreak) {
+    VERIFY_OR_DEBUG_ASSERT(!s_logfile.isOpen()) {
         // Somebody already called Logging::initialize.
         return;
     }
 
     setLogLevel(logLevel);
-    g_logFlushLevel = logFlushLevel;
+    s_logFlushLevel = logFlushLevel;
 
     QString logFileName;
 
@@ -178,20 +260,19 @@ void Logging::initialize(const QDir& settingsDir,
                 QFile::remove(olderlogname);
             }
             if (!QFile::rename(logFileName, olderlogname)) {
-                fprintf(stderr, "Error rolling over logfile %s",
-                        logFileName.toLocal8Bit().constData());
+                fprintf(stderr, "Error rolling over logfile %s", logFileName.toLocal8Bit().constData());
             }
         }
     }
 
-    // Since the message handler is not installed yet, we can touch g_logfile
+    // Since the message handler is not installed yet, we can touch s_logfile
     // without the lock.
-    g_logfile.setFileName(logFileName);
-    g_logfile.open(QIODevice::WriteOnly | QIODevice::Text);
-    g_debugAssertBreak = debugAssertBreak;
+    s_logfile.setFileName(logFileName);
+    s_logfile.open(QIODevice::WriteOnly | QIODevice::Text);
+    s_debugAssertBreak = debugAssertBreak;
 
     // Install the Qt message handler.
-    qInstallMessageHandler(MessageHandler);
+    qInstallMessageHandler(handleMessage);
 
     // Ugly hack around distributions disabling debugging in Qt applications.
     // This restores the default Qt behavior. It is required for getting useful
@@ -201,35 +282,31 @@ void Logging::initialize(const QDir& settingsDir,
     // Ubuntu: https://bugs.launchpad.net/ubuntu/+source/qtbase-opensource-src/+bug/1731646
     // Somehow this causes a segfault on macOS though?? https://bugs.launchpad.net/mixxx/+bug/1871238
 #ifdef __LINUX__
-    QLoggingCategory::setFilterRules("*.debug=true\n"
-                                     "qt.*.debug=false");
+    QLoggingCategory::setFilterRules(
+            "*.debug=true\n"
+            "qt.*.debug=false");
 #endif
 }
 
 // static
-void Logging::setLogLevel(LogLevel logLevel) {
-    g_logLevel = logLevel;
-}
-
-// static
 void Logging::shutdown() {
     // Reset the Qt message handler to default.
     qInstallMessageHandler(nullptr);
 
     // Even though we uninstalled the message handler, other threads may have
     // already entered it.
-    QMutexLocker locker(&g_mutexLogfile);
-    if (g_logfile.isOpen()) {
-        g_logfile.close();
+    QMutexLocker locker(&s_mutexLogfile);
+    if (s_logfile.isOpen()) {
+        s_logfile.close();
     }
 }
 
 // static
 void Logging::flushLogFile() {
-    QMutexLocker locker(&g_mutexLogfile);
-    if (g_logfile.isOpen()) {
-        g_logfile.flush();
+    QMutexLocker locker(&s_mutexLogfile);
+    if (s_logfile.isOpen()) {
+        s_logfile.flush();
     }
 }
 
-}  // namespace mixxx
+} // namespace mixxx
diff --git a/src/util/logging.h b/src/util/logging.h
index 79f71eb927..a52a280d64 100644
--- a/src/util/logging.h
+++ b/src/util/logging.h
@@ -1,9 +1,7 @@
-#ifndef MIXXX_UTIL_LOGGING_H
-#define MIXXX_UTIL_LOGGING_H
+#pragma once
 
 #include <QDir>
 
-
 namespace mixxx {
 
 enum class LogLevel {
@@ -11,54 +9,57 @@ enum class LogLevel {
     Warning = 1,
     Info = 2,
     Debug = 3,
-    Trace = 4, // for profiling etc.
+    Trace = 4, // DEPRECATED (not available in Qt, used for profiling etc.)
 };
 
+/// Default log level for (console) logs.
 constexpr LogLevel kLogLevelDefault = LogLevel::Warning;
-constexpr LogLevel kLogFlushLevelDefault = LogLevel::Critical;
 
-// Almost constant, i.e. initialized once at startup
-// TODO(XXX): Remove this ugly "extern" hack after getting rid of
-// the broken plugin architecture. Both globals should (again)
-// become static members of the class Logging.
-extern LogLevel g_logLevel;
-extern LogLevel g_logFlushLevel;
+/// Default log level for flushing the buffered log stream.
+/// This is required to ensure that all buffered messages have
+/// been written before Mixxx crashes.
+constexpr LogLevel kLogFlushLevelDefault = LogLevel::Critical;
 
+/// Utility class for accessing the logging settings that are
+/// configured at startup.
 class Logging {
   public:
     // These are not thread safe. Only call them on Mixxx startup and shutdown.
-    static void initialize(const QDir& settingsDir,
-                           LogLevel logLevel,
-                           LogLevel logFlushLevel,
-                           bool debugAssertBreak);
+    static void initialize(
+            const QDir& settingsDir,
+            LogLevel logLevel,
+            LogLevel logFlushLevel,
+            bool debugAssertBreak);
 
-    // Sets only the loglevel without the on-disk settings.  Used by mixxx-test.
-    static void setLogLevel(LogLevel logLevel);
+    // Sets only the loglevel without the on-disk settings. Used by mixxx-test.
+    static void setLogLevel(
+            LogLevel logLevel) {
+        s_logLevel = logLevel;
+    }
 
     static void shutdown();
 
     static void flushLogFile();
 
-    static bool enabled(LogLevel logLevel) {
-        return g_logLevel >= logLevel;
-    }
-    static bool flushing(LogLevel logFlushLevel) {
-        return g_logFlushLevel >= logFlushLevel;
+    static bool shouldFlush(
+            LogLevel logFlushLevel) {
+        // Log levels are ordered by severity, i.e. more
+        // severe log levels have a lower ordinal
+        return s_logFlushLevel >= logFlushLevel;
     }
-    static bool traceEnabled() {
-        return enabled(LogLevel::Trace);
-    }
-    static bool debugEnabled() {
-        return enabled(LogLevel::Debug);
-    }
-    static bool infoEnabled() {
-        return enabled(LogLevel::Info);
+
+    static bool enabled(
+            LogLevel logLevel) {
+        return s_logLevel >= logLevel;
     }
 
   private:
+    // Almost constant, i.e. initialized once at startup and
+    // then could safely be read from multiple threads.
+    static LogLevel s_logLevel;
+    static LogLevel s_logFlushLevel;
+
     Logging() = delete;
 };
 
-}  // namespace mixxx
-
-#endif /* MIXXX_UTIL_LOGGING_H */
+} // namespace mixxx