core/log: add custom log encoder for smaller log storage

Will be used to store more detailed logs in the future without using
as much disk space.
This commit is contained in:
outfoxxed 2024-08-09 14:43:18 -07:00
parent 8364e94d26
commit bdbf5b9af9
Signed by: outfoxxed
GPG key ID: 4C88A185FB89301E
9 changed files with 980 additions and 87 deletions

View file

@ -1,24 +1,86 @@
#include "logging.hpp"
#include <array>
#include <cstdio>
#include <cstring>
#include <qbytearrayview.h>
#include <qdatetime.h>
#include <qendian.h>
#include <qhashfunctions.h>
#include <qlogging.h>
#include <qloggingcategory.h>
#include <qnamespace.h>
#include <qobject.h>
#include <qobjectdefs.h>
#include <qstring.h>
#include <qsysinfo.h>
#include <qtenvironmentvariables.h>
#include <qtextstream.h>
#include <qthread.h>
#include <qtmetamacros.h>
#include <qtypes.h>
#include <sys/mman.h>
#include <sys/sendfile.h>
#include "logging_p.hpp"
#include "paths.hpp"
namespace qs::log {
Q_LOGGING_CATEGORY(logLogging, "quickshell.logging", QtWarningMsg);
bool LogMessage::operator==(const LogMessage& other) const {
// note: not including time
return this->type == other.type && this->category == other.category && this->body == other.body;
}
size_t qHash(const LogMessage& message) {
return qHash(message.type) ^ qHash(message.category) ^ qHash(message.body);
}
void LogMessage::formatMessage(
QTextStream& stream,
const LogMessage& msg,
bool color,
bool timestamp
) {
if (timestamp) {
if (color) stream << "\033[90m";
stream << msg.time.toString("yyyy-MM-dd hh:mm:ss.zzz");
}
if (color) {
switch (msg.type) {
case QtDebugMsg: stream << "\033[34m DEBUG"; break;
case QtInfoMsg: stream << "\033[32m INFO"; break;
case QtWarningMsg: stream << "\033[33m WARN"; break;
case QtCriticalMsg: stream << "\033[31m ERROR"; break;
case QtFatalMsg: stream << "\033[31m FATAL"; break;
}
} else {
switch (msg.type) {
case QtDebugMsg: stream << " DEBUG"; break;
case QtInfoMsg: stream << " INFO"; break;
case QtWarningMsg: stream << " WARN"; break;
case QtCriticalMsg: stream << " ERROR"; break;
case QtFatalMsg: stream << " FATAL"; break;
}
}
const auto isDefault = msg.category == "default";
if (color && !isDefault && msg.type != QtFatalMsg) stream << "\033[97m";
if (!isDefault) {
stream << ' ' << msg.category;
}
if (color && msg.type != QtFatalMsg) stream << "\033[0m";
stream << ": " << msg.body;
if (color && msg.type == QtFatalMsg) stream << "\033[0m";
}
LogManager::LogManager()
: colorLogs(qEnvironmentVariableIsEmpty("NO_COLOR"))
, stdoutStream(stdout) {}
@ -28,11 +90,11 @@ void LogManager::messageHandler(
const QMessageLogContext& context,
const QString& msg
) {
auto message = LogMessage(type, context.category, msg.toUtf8());
auto message = LogMessage(type, QLatin1StringView(context.category), msg.toUtf8());
auto* self = LogManager::instance();
LogManager::formatMessage(self->stdoutStream, message, self->colorLogs, false);
LogMessage::formatMessage(self->stdoutStream, message, self->colorLogs, false);
self->stdoutStream << Qt::endl;
emit self->logMessage(message);
@ -64,50 +126,6 @@ void LogManager::initFs() {
);
}
void LogManager::formatMessage(
QTextStream& stream,
const LogMessage& msg,
bool color,
bool timestamp
) {
if (timestamp) {
if (color) stream << "\033[90m";
stream << msg.time.toString("yyyy-MM-dd hh:mm:ss.zzz");
}
if (color) {
switch (msg.type) {
case QtDebugMsg: stream << "\033[34m DEBUG"; break;
case QtInfoMsg: stream << "\033[32m INFO"; break;
case QtWarningMsg: stream << "\033[33m WARN"; break;
case QtCriticalMsg: stream << "\033[31m ERROR"; break;
case QtFatalMsg: stream << "\033[31m FATAL"; break;
}
} else {
switch (msg.type) {
case QtDebugMsg: stream << " DEBUG"; break;
case QtInfoMsg: stream << " INFO"; break;
case QtWarningMsg: stream << " WARN"; break;
case QtCriticalMsg: stream << " ERROR"; break;
case QtFatalMsg: stream << " FATAL"; break;
}
}
const auto isDefault = strcmp(msg.category, "default") == 0;
if (color && !isDefault && msg.type != QtFatalMsg) stream << "\033[97m";
if (!isDefault) {
stream << ' ' << msg.category;
}
if (color && msg.type != QtFatalMsg) stream << "\033[0m";
stream << ": " << msg.body;
if (color && msg.type == QtFatalMsg) stream << "\033[0m";
}
void LoggingThreadProxy::initInThread() {
this->logging = new ThreadLogging(this);
this->logging->init();
@ -116,17 +134,39 @@ void LoggingThreadProxy::initInThread() {
void LoggingThreadProxy::initFs() { this->logging->initFs(); }
void ThreadLogging::init() {
auto mfd = memfd_create("quickshell:logs", 0);
auto logMfd = memfd_create("quickshell:logs", 0);
if (mfd == -1) {
if (logMfd == -1) {
qCCritical(logLogging) << "Failed to create memfd for initial log storage"
<< qt_error_string(-1);
return;
}
this->file = new QFile();
this->file->open(mfd, QFile::WriteOnly, QFile::AutoCloseHandle);
this->fileStream.setDevice(this->file);
auto dlogMfd = memfd_create("quickshell:detailedlogs", 0);
if (dlogMfd == -1) {
qCCritical(logLogging) << "Failed to create memfd for initial detailed log storage"
<< qt_error_string(-1);
}
if (logMfd != -1) {
this->file = new QFile();
this->file->open(logMfd, QFile::WriteOnly, QFile::AutoCloseHandle);
this->fileStream.setDevice(this->file);
}
if (dlogMfd != -1) {
this->detailedFile = new QFile();
// buffered by WriteBuffer
this->detailedFile->open(dlogMfd, QFile::WriteOnly | QFile::Unbuffered, QFile::AutoCloseHandle);
this->detailedWriter.setDevice(this->detailedFile);
if (!this->detailedWriter.writeHeader()) {
qCCritical(logLogging) << "Could not write header for detailed logs.";
this->detailedWriter.setDevice(nullptr);
delete this->detailedFile;
this->detailedFile = nullptr;
}
}
// This connection is direct so it works while the event loop is destroyed between
// QCoreApplication delete and Q(Gui)Application launch.
@ -138,11 +178,11 @@ void ThreadLogging::init() {
Qt::DirectConnection
);
qCDebug(logLogging) << "Created memfd" << mfd << "for early logs.";
qCDebug(logLogging) << "Created memfd" << logMfd << "for early logs.";
qCDebug(logLogging) << "Created memfd" << dlogMfd << "for early detailed logs.";
}
void ThreadLogging::initFs() {
qCDebug(logLogging) << "Starting filesystem logging...";
auto* runDir = QsPaths::instance()->instanceRunDir();
@ -153,23 +193,62 @@ void ThreadLogging::initFs() {
}
auto path = runDir->filePath("log.log");
auto detailedPath = runDir->filePath("log.qslog");
auto* file = new QFile(path);
auto* detailedFile = new QFile(detailedPath);
if (!file->open(QFile::WriteOnly | QFile::Truncate)) {
qCCritical(logLogging
) << "Could not start filesystem logger as the log file could not be created:"
<< path;
return;
delete file;
file = nullptr;
}
// buffered by WriteBuffer
if (!detailedFile->open(QFile::WriteOnly | QFile::Truncate | QFile::Unbuffered)) {
qCCritical(logLogging
) << "Could not start detailed filesystem logger as the log file could not be created:"
<< detailedPath;
delete detailedFile;
detailedFile = nullptr;
}
qCDebug(logLogging) << "Copying memfd logs to log file...";
auto* oldFile = this->file;
oldFile->seek(0);
sendfile(file->handle(), oldFile->handle(), nullptr, oldFile->size());
this->file = file;
this->fileStream.setDevice(file);
delete oldFile;
if (file) {
auto* oldFile = this->file;
if (oldFile) {
oldFile->seek(0);
sendfile(file->handle(), oldFile->handle(), nullptr, oldFile->size());
}
this->file = file;
this->fileStream.setDevice(file);
delete oldFile;
}
if (detailedFile) {
auto* oldFile = this->detailedFile;
if (oldFile) {
oldFile->seek(0);
sendfile(detailedFile->handle(), oldFile->handle(), nullptr, oldFile->size());
}
this->detailedFile = detailedFile;
this->detailedWriter.setDevice(detailedFile);
if (!oldFile) {
if (!this->detailedWriter.writeHeader()) {
qCCritical(logLogging) << "Could not write header for detailed logs.";
this->detailedWriter.setDevice(nullptr);
delete this->detailedFile;
this->detailedFile = nullptr;
}
}
delete oldFile;
}
qCDebug(logLogging) << "Switched logging to disk logs.";
@ -189,6 +268,360 @@ void ThreadLogging::initFs() {
void ThreadLogging::onMessage(const LogMessage& msg) {
if (this->fileStream.device() == nullptr) return;
LogManager::formatMessage(this->fileStream, msg, false, true);
LogMessage::formatMessage(this->fileStream, msg, false, true);
this->fileStream << Qt::endl;
if (this->detailedWriter.write(msg)) {
this->detailedFile->flush();
} else if (this->detailedFile != nullptr) {
qCCritical(logLogging) << "Detailed logger failed to write. Ending detailed logs.";
}
}
CompressedLogType compressedTypeOf(QtMsgType type) {
switch (type) {
case QtDebugMsg: return CompressedLogType::Debug;
case QtInfoMsg: return CompressedLogType::Info;
case QtWarningMsg: return CompressedLogType::Warn;
case QtCriticalMsg:
case QtFatalMsg: return CompressedLogType::Critical;
}
}
QtMsgType typeOfCompressed(CompressedLogType type) {
switch (type) {
case CompressedLogType::Debug: return QtDebugMsg;
case CompressedLogType::Info: return QtInfoMsg;
case CompressedLogType::Warn: return QtWarningMsg;
case CompressedLogType::Critical: return QtCriticalMsg;
}
}
void WriteBuffer::setDevice(QIODevice* device) { this->device = device; }
bool WriteBuffer::hasDevice() const { return this->device; }
bool WriteBuffer::flush() {
auto written = this->device->write(this->buffer);
auto success = written == this->buffer.length();
this->buffer.clear();
return success;
}
void WriteBuffer::writeBytes(const char* data, qsizetype length) {
this->buffer.append(data, length);
}
void WriteBuffer::writeU8(quint8 data) {
this->writeBytes(reinterpret_cast<char*>(&data), 1); // NOLINT
}
void WriteBuffer::writeU16(quint16 data) {
data = qToLittleEndian(data);
this->writeBytes(reinterpret_cast<char*>(&data), 2); // NOLINT
}
void WriteBuffer::writeU32(quint32 data) {
data = qToLittleEndian(data);
this->writeBytes(reinterpret_cast<char*>(&data), 4); // NOLINT
}
void WriteBuffer::writeU64(quint64 data) {
data = qToLittleEndian(data);
this->writeBytes(reinterpret_cast<char*>(&data), 8); // NOLINT
}
void DeviceReader::setDevice(QIODevice* device) { this->device = device; }
bool DeviceReader::hasDevice() const { return this->device; }
bool DeviceReader::readBytes(char* data, qsizetype length) {
return this->device->read(data, length) == length;
}
qsizetype DeviceReader::peekBytes(char* data, qsizetype length) {
return this->device->peek(data, length);
}
bool DeviceReader::skip(qsizetype length) { return this->device->skip(length) == length; }
bool DeviceReader::readU8(quint8* data) {
return this->readBytes(reinterpret_cast<char*>(data), 1); // NOLINT
}
bool DeviceReader::readU16(quint16* data) {
return this->readBytes(reinterpret_cast<char*>(data), 2); // NOLINT
}
bool DeviceReader::readU32(quint32* data) {
return this->readBytes(reinterpret_cast<char*>(data), 4); // NOLINT
}
bool DeviceReader::readU64(quint64* data) {
return this->readBytes(reinterpret_cast<char*>(data), 8); // NOLINT
}
void EncodedLogWriter::setDevice(QIODevice* target) { this->buffer.setDevice(target); }
void EncodedLogReader::setDevice(QIODevice* source) { this->reader.setDevice(source); }
constexpr quint8 LOG_VERSION = 1;
bool EncodedLogWriter::writeHeader() {
this->buffer.writeU8(LOG_VERSION);
return this->buffer.flush();
}
bool EncodedLogReader::readHeader(bool* success, quint8* version, quint8* readerVersion) {
if (!this->reader.readU8(version)) return false;
*success = *version == LOG_VERSION;
*readerVersion = LOG_VERSION;
return true;
}
bool EncodedLogWriter::write(const LogMessage& message) {
if (!this->buffer.hasDevice()) return false;
LogMessage* prevMessage = nullptr;
auto index = this->recentMessages.indexOf(message, &prevMessage);
// If its a dupe, save memory by reusing the buffer of the first message and letting
// the new one be deallocated.
auto body = prevMessage ? prevMessage->body : message.body;
this->recentMessages.emplace(message.type, message.category, body, message.time);
if (index != -1) {
auto secondDelta = this->lastMessageTime.secsTo(message.time);
if (secondDelta < 16 && index < 16) {
this->writeOp(EncodedLogOpcode::RecentMessageShort);
this->buffer.writeU8(index | (secondDelta << 4));
} else {
this->writeOp(EncodedLogOpcode::RecentMessageLong);
this->buffer.writeU8(index);
this->writeVarInt(secondDelta);
}
goto finish;
} else {
auto categoryId = this->getOrCreateCategory(message.category);
this->writeVarInt(categoryId);
auto writeFullTimestamp = [this, &message]() {
this->buffer.writeU64(message.time.toSecsSinceEpoch());
};
if (message.type == QtFatalMsg) {
this->buffer.writeU8(0xff);
writeFullTimestamp();
} else {
quint8 field = compressedTypeOf(message.type);
auto secondDelta = this->lastMessageTime.secsTo(message.time);
if (secondDelta > 29) {
// 0x1d = followed by delta int
// 0x1e = followed by epoch delta int
field |= (secondDelta < 0xffff ? 0x1d : 0x1e) << 3;
} else {
field |= secondDelta << 3;
}
this->buffer.writeU8(field);
if (secondDelta > 29) {
if (secondDelta > 0xffff) {
writeFullTimestamp();
} else {
this->writeVarInt(secondDelta);
}
}
}
this->writeString(message.body);
}
finish:
// copy with second precision
this->lastMessageTime = QDateTime::fromSecsSinceEpoch(message.time.toSecsSinceEpoch());
return this->buffer.flush();
}
bool EncodedLogReader::read(LogMessage* slot) {
start:
quint32 next = 0;
if (!this->readVarInt(&next)) return false;
if (next < EncodedLogOpcode::BeginCategories) {
if (next == EncodedLogOpcode::RegisterCategory) {
if (!this->registerCategory()) return false;
goto start;
} else if (next == EncodedLogOpcode::RecentMessageShort || next == EncodedLogOpcode::RecentMessageLong)
{
quint8 index = 0;
quint32 secondDelta = 0;
if (next == EncodedLogOpcode::RecentMessageShort) {
quint8 field = 0;
if (!this->reader.readU8(&field)) return false;
index = field & 0xf;
secondDelta = field >> 4;
} else {
if (!this->reader.readU8(&index)) return false;
if (!this->readVarInt(&secondDelta)) return false;
}
*slot = this->recentMessages.at(index);
this->lastMessageTime = this->lastMessageTime.addSecs(static_cast<qint64>(secondDelta));
slot->time = this->lastMessageTime;
}
} else {
auto category = this->categories.value(next - EncodedLogOpcode::BeginCategories);
quint8 field = 0;
if (!this->reader.readU8(&field)) return false;
auto msgType = QtDebugMsg;
quint64 secondDelta = 0;
auto needsTimeRead = false;
if (field == 0xff) {
msgType = QtFatalMsg;
needsTimeRead = true;
} else {
msgType = typeOfCompressed(static_cast<CompressedLogType>(field & 0x07));
secondDelta = field >> 3;
if (secondDelta == 0x1d) {
quint32 slot = 0;
if (!this->readVarInt(&slot)) return false;
secondDelta = slot;
} else if (secondDelta == 0x1e) {
needsTimeRead = true;
}
}
if (needsTimeRead) {
if (!this->reader.readU64(&secondDelta)) return false;
}
this->lastMessageTime = this->lastMessageTime.addSecs(static_cast<qint64>(secondDelta));
QByteArray body;
if (!this->readString(&body)) return false;
*slot = LogMessage(msgType, QLatin1StringView(category), body, this->lastMessageTime);
}
this->recentMessages.emplace(*slot);
return true;
}
void EncodedLogWriter::writeOp(EncodedLogOpcode opcode) { this->buffer.writeU8(opcode); }
void EncodedLogWriter::writeVarInt(quint32 n) {
if (n < 0xff) {
this->buffer.writeU8(n);
} else if (n < 0xffff) {
this->buffer.writeU8(0xff);
this->buffer.writeU16(n);
} else {
this->buffer.writeU8(0xff);
this->buffer.writeU16(0xffff);
this->buffer.writeU32(n);
}
}
bool EncodedLogReader::readVarInt(quint32* slot) {
auto bytes = std::array<quint8, 7>();
auto readLength = this->reader.peekBytes(reinterpret_cast<char*>(bytes.data()), 7); // NOLINT
if (bytes[0] != 0xff && readLength >= 1) {
auto n = *reinterpret_cast<quint8*>(bytes.data()); // NOLINT
if (!this->reader.skip(1)) return false;
*slot = qFromLittleEndian(n);
} else if ((bytes[1] != 0xff || bytes[2] != 0xff) && readLength >= 3) {
auto n = *reinterpret_cast<quint16*>(bytes.data() + 1); // NOLINT
if (!this->reader.skip(3)) return false;
*slot = qFromLittleEndian(n);
} else if (readLength == 7) {
auto n = *reinterpret_cast<quint32*>(bytes.data() + 3); // NOLINT
if (!this->reader.skip(7)) return false;
*slot = qFromLittleEndian(n);
} else return false;
return true;
}
void EncodedLogWriter::writeString(QByteArrayView bytes) {
this->writeVarInt(bytes.length());
this->buffer.writeBytes(bytes.constData(), bytes.length());
}
bool EncodedLogReader::readString(QByteArray* slot) {
quint32 length = 0;
if (!this->readVarInt(&length)) return false;
*slot = QByteArray(length, Qt::Uninitialized);
auto r = this->reader.readBytes(slot->data(), slot->size());
return r;
}
quint16 EncodedLogWriter::getOrCreateCategory(QLatin1StringView category) {
if (this->categories.contains(category)) {
return this->categories.value(category);
} else {
this->writeOp(EncodedLogOpcode::RegisterCategory);
// id is implicitly the next available id
this->writeString(category);
auto id = this->nextCategory++;
this->categories.insert(category, id);
return id;
}
}
bool EncodedLogReader::registerCategory() {
QByteArray name;
if (!this->readString(&name)) return false;
this->categories.append(name);
return true;
}
bool readEncodedLogs(QIODevice* device) {
auto reader = EncodedLogReader();
reader.setDevice(device);
bool readable = false;
quint8 logVersion = 0;
quint8 readerVersion = 0;
if (!reader.readHeader(&readable, &logVersion, &readerVersion)) {
qCritical() << "Failed to read log header.";
return false;
}
if (!readable) {
qCritical() << "This log was encoded with version" << logVersion
<< "of the quickshell log encoder, which cannot be decoded by the current "
"version of quickshell, with log version"
<< readerVersion;
return false;
}
auto color = LogManager::instance()->colorLogs;
LogMessage message;
auto stream = QTextStream(stdout);
while (reader.read(&message)) {
LogMessage::formatMessage(stream, message, color, true);
stream << '\n';
}
stream << Qt::flush;
if (!device->atEnd()) {
qCritical() << "An error occurred parsing the end of this log file.";
qCritical() << "Remaining data:" << device->readAll();
}
return true;
}
} // namespace qs::log