path: root/src/util/logging.cpp

#include "util/logging.h"

#include <signal.h>
#include <stdio.h>

#include <QByteArray>
#include <QFile>
#include <QFileInfo>
#include <QIODevice>
#include <QLoggingCategory>
#include <QMutex>
#include <QString>
#include <QTextStream>
#include <QThread>
#include <string_view>

#include "util/assert.h"
#include "util/cmdlineargs.h"
#include "util/compatibility/qmutex.h"

namespace {

/// Mutex guarding s_logfile.
QMutex s_mutexLogfile;

/// Mutex guarding stderr.
QMutex s_mutexStdErr;

// The file handle for Mixxx's log file.
QFile s_logfile;

QLoggingCategory::CategoryFilter oldCategoryFilter = nullptr;

/// Logging category for messages logged via the JavaScript Console API.
constexpr std::string_view jsLoggingCategory = {"js"};

/// Logging category prefix for messages logged by the controller system.
constexpr std::string_view controllerLoggingCategoryPrefix = {"controller."};

/// Filters logging categories for the `--controller-debug` command line
/// argument, so that debug messages are enabled for all categories in the
/// `controller` namespace, and disabled for all other categories.
void controllerDebugCategoryFilter(QLoggingCategory* category) {
    // Configure `js` or `controller.*` categories here, otherwise forward to to default filter.
    const std::string_view categoryName{category->categoryName()};
    // TODO: Use `categoryName.starts_with(controllerLoggingCategoryPrefix)` once we switch to C++20.
    if (categoryName == jsLoggingCategory ||
            categoryName.substr(0,
                    std::min(categoryName.size(),
                            controllerLoggingCategoryPrefix.size())) ==
                    controllerLoggingCategoryPrefix) {
        // If the logging category name starts with `controller.`, show debug messages.
        category->setEnabled(QtDebugMsg, true);
    } else {
        // Otherwise, pass it on to the default filter (via function pointer)
        // and disable all debug messages for those categories.
        oldCategoryFilter(category);
        category->setEnabled(QtDebugMsg, false);
    }
}

// The log level.
// Whether to break on debug assertions.
bool s_debugAssertBreak = false;

// Note:
// you can customize this pattern by starting Mixxx with
// QT_MESSAGE_PATTERN="%{message}" mixxx
// For debugging timing related issues
// QT_MESSAGE_PATTERN="%{time yyyyMMdd h:mm:ss.zzz} %{type} [{{threadname}}] %{message}"
// Or for for finding the origin (in Debug builds)
// QT_MESSAGE_PATTERN="%{type} [{{threadname}}] %{file}:%{line} %{message}"
// QT_MESSAGE_PATTERN="%{type} [{{threadname}}] %{function} %{message}"
// TODO: Adjust the default format and messages and collect file and function info in release builds as well.

const QString kThreadNamePattern = QStringLiteral("{{threadname}}");
const QString kDefaultMessagePattern = QStringLiteral("%{type} [") +
        kThreadNamePattern + QStringLiteral("] %{message}");

const QString kDefaultMessagePatternColor =
        QStringLiteral(
                "%{if-category}\033[35m %{category}:\033[35m%{endif}"
                "%{if-debug}\033[34m%{type}%{endif}"
                "%{if-info}\033[32m%{type}%{endif}"
                "%{if-warning}\033[93m%{type}%{endif}"
                "%{if-critical}\033[91m%{type}%{endif}"
                "\033[0m [\033[97m") +
        kThreadNamePattern +
        QStringLiteral(
                "\033[0m] "
                "%{if-fatal}\033[97m\033[41m%{type} "
                "\033[30m%{file}:%{line}\033[0m %{endif}"
                "%{message}");

const QLoggingCategory kDefaultLoggingCategory = QLoggingCategory(nullptr);

enum class WriteFlag {
    None = 0,
    StdErr = 1 << 0,
    File = 1 << 1,
    Flush = 1 << 2,
    All = StdErr | File | Flush,
};

Q_DECLARE_FLAGS(WriteFlags, WriteFlag)

// Clang 10 complains about an unused function introduced by
// Q_DECLARE_OPERATORS_FOR_FLAGS
#if defined(__clang__)
#pragma clang diagnostic push
#pragma clang diagnostic ignored "-Wunused-function"
#endif
Q_DECLARE_OPERATORS_FOR_FLAGS(WriteFlags)
#if defined(__clang__)
#pragma clang diagnostic pop
#endif

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

    const auto locked = lockMutex(&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();

    const auto locked = lockMutex(&s_mutexStdErr);
    const std::size_t written = fwrite(
            formattedMessage.constData(), sizeof(char), formattedMessage.size(), stderr);
    Q_UNUSED(written);
    DEBUG_ASSERT(written == static_cast<size_t>(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);
    }
}

/// Rotate existing logfiles and get the file path of the log file to write to.
/// May return an invalid/empty QString if the log directory does not exist.
QString rotateLogFilesAndGetFilePath(const QString& logDirPath) {
    if (logDirPath.isEmpty()) {
        fprintf(stderr, "No log directory specified!\n");
        return QString();
    }

    QDir logDir(logDirPath);
    if (!logDir.exists()) {
        fprintf(stderr,
                "Log directory %s does not exist!\n",
                logDir.absolutePath().toLocal8Bit().constData());
        return QString();
    }

    QString logFilePath;
    // Rotate old logfiles.
    for (int i = 9; i >= 0; --i) {
        const QString logFileName = (i == 0) ? QString("mixxx.log")
                                             : QString("mixxx.log.%1").arg(i);
        logFilePath = logDir.absoluteFilePath(logFileName);
        if (QFileInfo::exists(logFilePath)) {
            QString olderLogFilePath =
                    logDir.absoluteFilePath(QString("mixxx.log.%1").arg(i + 1));
            // This should only happen with number 10
            if (QFileInfo::exists(olderLogFilePath)) {
                QFile::remove(olderLogFilePath);
            }
            if (!QFile::rename(logFilePath, olderLogFilePath)) {
                fprintf(stderr,
                        "Error rolling over logfile %s\n",
                        logFilePath.toLocal8Bit().constData());
            }
        }
    }
    return logFilePath;
}

/// Handles writing to stderr and the log file.
inline void writeToLog(
        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 &