Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

logging: Add support for QT_MESSAGE_PATTERN env var #3204

Merged
merged 7 commits into from
Oct 24, 2020
Merged

logging: Add support for QT_MESSAGE_PATTERN env var #3204

Changes from 6 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
023058c
logging: Add support for QT_MESSAGE_PATTERN env var
Holzhaus Oct 22, 2020
f8810d0
logging: Ensure a fixed format for log files
Holzhaus Oct 23, 2020
df034bd
logging: Add mutex for writing to stderr
Holzhaus Oct 23, 2020
938c962
logging: Fix handling of threadname in pattern
Holzhaus Oct 23, 2020
50195a4
logging: Fix some minor style issues and improve thread ptr handling
Holzhaus Oct 23, 2020
7640a26
logging: Use a global constant for default message pattern
Holzhaus Oct 23, 2020
f38755e
logging: Remove stray empty line
Holzhaus Oct 23, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
201 changes: 112 additions & 89 deletions src/util/logging.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,16 +19,23 @@

namespace {

// Mutex guarding s_logfile.
/// Mutex guarding s_logfile.
QMutex s_mutexLogfile;

/// Mutex guarding stderr.
QMutex s_mutexStdErr;
Holzhaus marked this conversation as resolved.
Show resolved Hide resolved

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

// The log level.
// 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 {
Expand All @@ -43,41 +50,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 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<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);
}
}

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

Expand All @@ -93,15 +169,13 @@ 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:
levelName = "Debug";
baSize += strlen(levelName);
isControllerDebug =
input.startsWith(QLatin1String(
ControllerDebug::kLogMessagePrefix));
Expand All @@ -121,7 +195,6 @@ void handleMessage(
break;
case QtInfoMsg:
levelName = "Info";
baSize += strlen(levelName);
if (Logging::enabled(LogLevel::Info)) {
writeFlags |= WriteFlag::StdErr;
}
Expand All @@ -133,7 +206,6 @@ void handleMessage(
break;
case QtWarningMsg:
levelName = "Warning";
baSize += strlen(levelName);
if (Logging::enabled(LogLevel::Warning)) {
writeFlags |= WriteFlag::StdErr;
}
Expand All @@ -145,13 +217,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;
}
Expand All @@ -163,60 +233,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;
Expand All @@ -226,12 +245,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
Expand Down Expand Up @@ -291,6 +310,10 @@ void Logging::initialize(

s_debugAssertBreak = debugAssertBreak;

if (qgetenv("QT_MESSAGE_PATTERN").isEmpty()) {
qSetMessagePattern(kDefaultMessagePattern);
}

// Install the Qt message handler.
qInstallMessageHandler(handleMessage);

Expand Down