EnderTheCoder
2f6ff74670
Dated record timestamps, per-sink timestamp format, and archive names that keep the extension last (<stem>.<timestamp>.<ext>).
574 lines
24 KiB
C++
574 lines
24 KiB
C++
/**
|
|
* Logging with call-stack capture.
|
|
*
|
|
* Records carry a level, message, source location and — for severe enough
|
|
* levels — a formatted `std::stacktrace`. Capturing a trace walks the stack and
|
|
* reads debug information, so it is only done when the record's level is at or
|
|
* above `options::stacktrace_from`, and the whole call is skipped when the
|
|
* level is disabled.
|
|
*
|
|
* `std::stacktrace` is implemented by libstdc++ only. With GCC the module has
|
|
* to link `stdc++exp` (the static library that implements it); the CMake target
|
|
* takes care of that. File and line numbers in the trace come from debug
|
|
* information, so build with `-g` (Debug or RelWithDebInfo) to see them; symbol
|
|
* names work in any build.
|
|
*/
|
|
module;
|
|
|
|
// libc++ (the OpenRA3 toolchain) has no <stacktrace>, so this vendored copy adds
|
|
// a native fallback for the frames: Windows CaptureStackBackTrace and POSIX
|
|
// execinfo. These live in the global module fragment because they are C headers.
|
|
#if defined(_WIN32)
|
|
#define WIN32_LEAN_AND_MEAN
|
|
#define NOMINMAX
|
|
#include <windows.h>
|
|
#elif (defined(__unix__) || defined(__APPLE__)) && !defined(__EMSCRIPTEN__)
|
|
#include <execinfo.h>
|
|
#endif
|
|
|
|
export module ender.log;
|
|
|
|
import std;
|
|
|
|
export namespace ender::log {
|
|
/** Severity of a record, ordered from most to least verbose. */
|
|
enum class level: std::uint8_t {
|
|
trace = 0,
|
|
debug,
|
|
info,
|
|
warn,
|
|
error,
|
|
critical,
|
|
};
|
|
|
|
/** Short upper-case name of a level, for output. */
|
|
[[nodiscard]] inline auto to_string(const level severity) -> std::string_view {
|
|
switch (severity) {
|
|
case level::trace: return "TRACE";
|
|
case level::debug: return "DEBUG";
|
|
case level::info: return "INFO";
|
|
case level::warn: return "WARN";
|
|
case level::error: return "ERROR";
|
|
case level::critical: return "CRITICAL";
|
|
}
|
|
return "?";
|
|
}
|
|
|
|
/** Default timestamp rendered on a record, chrono format syntax. */
|
|
inline constexpr std::string_view default_time_format{"%Y-%m-%d %H:%M:%S"};
|
|
|
|
/** Logger configuration. */
|
|
struct options {
|
|
/** Records below this level are dropped before anything is built. */
|
|
level minimum{level::info};
|
|
/** Capture a stack trace for records at this level and above. */
|
|
level stacktrace_from{level::error};
|
|
/** Maximum number of frames kept in a captured trace. */
|
|
std::size_t stacktrace_depth{16};
|
|
/**
|
|
* Frames to drop from the top of a captured trace.
|
|
*
|
|
* The default drops `capture_stacktrace` and `emit`, which always exist
|
|
* as frames. The level wrappers are inlined away in optimised builds, so
|
|
* a fixed count cannot cover them; any leading frame that belongs to
|
|
* this module is therefore stripped by name instead, which keeps the
|
|
* caller visible whether or not the wrappers were inlined.
|
|
*/
|
|
std::size_t stacktrace_skip{2};
|
|
};
|
|
|
|
/** One log record. */
|
|
struct record {
|
|
level severity{level::info};
|
|
std::string message{};
|
|
std::string file{};
|
|
std::uint32_t line{0};
|
|
std::string function{};
|
|
/** Formatted call stack; empty when it was not captured. */
|
|
std::string stacktrace{};
|
|
std::chrono::system_clock::time_point time{};
|
|
std::thread::id thread{};
|
|
|
|
[[nodiscard]] auto has_stacktrace() const -> bool { return !stacktrace.empty(); }
|
|
};
|
|
|
|
namespace detail {
|
|
/**
|
|
* Render a time point with a runtime chrono format string.
|
|
*
|
|
* `std::format`'s format string is compile-time only, so the spec is
|
|
* wrapped in a replacement field and fed to `std::vformat`; a bare spec
|
|
* would be read as literal text rather than a chrono conversion.
|
|
*/
|
|
[[nodiscard]] inline auto format_time(const std::chrono::system_clock::time_point time,
|
|
const std::string_view time_format) -> std::string {
|
|
const auto moment = std::chrono::floor<std::chrono::seconds>(time);
|
|
const auto pattern = std::string{"{:"}.append(time_format).append("}");
|
|
return std::vformat(pattern, std::make_format_args(moment));
|
|
}
|
|
|
|
/**
|
|
* Render one record as a human-readable block: a header line and, when
|
|
* present, the indented stack frames. Shared by the stream sinks.
|
|
*
|
|
* @param time_format A chrono format string applied to the record's
|
|
* timestamp; defaults to the date and time of day.
|
|
*/
|
|
[[nodiscard]] inline auto format_record(const record &entry,
|
|
const std::string_view time_format = default_time_format)
|
|
-> std::string {
|
|
const auto stamp = format_time(entry.time, time_format);
|
|
auto text = std::format("[{}] {:<8} {}", stamp, to_string(entry.severity), entry.message);
|
|
if (!entry.file.empty()) {
|
|
text += std::format(" ({}:{})", entry.file, entry.line);
|
|
}
|
|
text += '\n';
|
|
if (entry.has_stacktrace()) {
|
|
text += entry.stacktrace;
|
|
}
|
|
return text;
|
|
}
|
|
}
|
|
|
|
/** Where records go. */
|
|
class sink {
|
|
public:
|
|
virtual ~sink() = default;
|
|
|
|
/** Receive one record; called with the logger's mutex held. */
|
|
virtual auto write(const record &entry) -> void = 0;
|
|
|
|
/** Flush any buffering. */
|
|
virtual auto flush() -> void {}
|
|
};
|
|
|
|
/** Writes a human-readable line per record to a stream (stderr by default). */
|
|
class console_sink final: public sink {
|
|
public:
|
|
explicit console_sink(std::ostream &stream = std::cerr,
|
|
std::string time_format = std::string{default_time_format})
|
|
: stream_(&stream), time_format_(std::move(time_format)) {}
|
|
|
|
auto write(const record &entry) -> void override {
|
|
*stream_ << detail::format_record(entry, time_format_);
|
|
stream_->flush();
|
|
}
|
|
|
|
private:
|
|
std::ostream *stream_;
|
|
std::string time_format_;
|
|
};
|
|
|
|
/** Keeps every record in memory; useful for tests and in-game consoles. */
|
|
class memory_sink final: public sink {
|
|
public:
|
|
auto write(const record &entry) -> void override {
|
|
const auto lock = std::scoped_lock{mutex_};
|
|
records_.push_back(entry);
|
|
}
|
|
|
|
[[nodiscard]] auto records() const -> std::vector<record> {
|
|
const auto lock = std::scoped_lock{mutex_};
|
|
return records_;
|
|
}
|
|
|
|
[[nodiscard]] auto size() const -> std::size_t {
|
|
const auto lock = std::scoped_lock{mutex_};
|
|
return records_.size();
|
|
}
|
|
|
|
auto clear() -> void {
|
|
const auto lock = std::scoped_lock{mutex_};
|
|
records_.clear();
|
|
}
|
|
|
|
private:
|
|
mutable std::mutex mutex_;
|
|
std::vector<record> records_;
|
|
};
|
|
|
|
/** Configuration for `file_sink`. */
|
|
struct file_options {
|
|
/** Move an existing log file aside to an archive when the sink opens it. */
|
|
bool archive_on_open{true};
|
|
/** Flush after every record, so the tail survives a crash. */
|
|
bool flush_each_record{true};
|
|
/** Rotate once the active file would grow past this many bytes; 0 disables. */
|
|
std::size_t max_file_size{0};
|
|
/** Keep at most this many archives, dropping the oldest first; 0 keeps them all. */
|
|
std::size_t max_archives{0};
|
|
/** Timestamp format used on each record's header line (chrono syntax). */
|
|
std::string timestamp_format{std::string{default_time_format}};
|
|
/** Chrono format for the timestamp inserted into archive names. */
|
|
std::string archive_time_format{"%Y%m%d-%H%M%S"};
|
|
};
|
|
|
|
/**
|
|
* Writes records to a file, archiving the previous one on open.
|
|
*
|
|
* `path` is the active file. When the sink opens it and the file already
|
|
* holds data, that file is renamed to a timestamped archive first, so a run
|
|
* never appends onto a previous run's log: every start begins a fresh file
|
|
* and the old one is preserved as `<stem>.<timestamp><extension>` (`.log`
|
|
* when the active file has no extension), where the timestamp is rendered by
|
|
* `file_options::archive_time_format` (default `<YYYYmmdd-HHMMSS>`). The same
|
|
* happens mid-run once the active file passes `file_options::max_file_size`.
|
|
* `file_options::max_archives` bounds how many archives are kept.
|
|
*
|
|
* As with every sink, `write` is called with the logger's mutex held, so one
|
|
* sink is safe to share; it is not safe for two processes to point at the
|
|
* same file.
|
|
*/
|
|
class file_sink final: public sink {
|
|
public:
|
|
explicit file_sink(std::filesystem::path path, const file_options options = {})
|
|
: path_(std::move(path)), options_(options) {
|
|
if (options_.archive_on_open && std::filesystem::exists(path_)) {
|
|
if (std::filesystem::file_size(path_) > 0) {
|
|
archive_current();
|
|
} else {
|
|
std::filesystem::remove(path_);
|
|
}
|
|
}
|
|
open();
|
|
}
|
|
|
|
auto write(const record &entry) -> void override {
|
|
const auto block = detail::format_record(entry, options_.timestamp_format);
|
|
// Rotate before writing, but never rotate an empty file: that would
|
|
// archive nothing and lose the record that is about to be written.
|
|
if (options_.max_file_size > 0 && size_ > 0 && size_ + block.size() > options_.max_file_size) {
|
|
archive_current();
|
|
open();
|
|
}
|
|
stream_ << block;
|
|
size_ += block.size();
|
|
if (options_.flush_each_record) stream_.flush();
|
|
}
|
|
|
|
auto flush() -> void override {
|
|
if (stream_.is_open()) stream_.flush();
|
|
}
|
|
|
|
/** The active log file. */
|
|
[[nodiscard]] auto path() const -> const std::filesystem::path & { return path_; }
|
|
|
|
/** Archives this sink created, oldest first. */
|
|
[[nodiscard]] auto archives() const -> const std::vector<std::filesystem::path> & { return archives_; }
|
|
|
|
private:
|
|
auto open() -> void {
|
|
stream_.clear();
|
|
stream_.open(path_, std::ios::out | std::ios::trunc | std::ios::binary);
|
|
size_ = 0;
|
|
}
|
|
|
|
auto archive_current() -> void {
|
|
if (stream_.is_open()) stream_.close();
|
|
const auto stamp = detail::format_time(std::chrono::system_clock::now(), options_.archive_time_format);
|
|
// Keep the extension last: `<stem>.<timestamp><extension>`, falling
|
|
// back to `.log` when the active file has none.
|
|
const auto stem = path_.stem().string();
|
|
const auto extension = path_.has_extension() ? path_.extension().string() : std::string{".log"};
|
|
auto archive = path_.parent_path() / (stem + "." + stamp + extension);
|
|
// Two rotations can land in the same second; disambiguate with a
|
|
// counter rather than overwrite the earlier archive.
|
|
for (auto counter = 1; std::filesystem::exists(archive); ++counter) {
|
|
archive = path_.parent_path() /
|
|
(stem + "." + stamp + "." + std::to_string(counter) + extension);
|
|
}
|
|
std::filesystem::rename(path_, archive);
|
|
archives_.push_back(archive);
|
|
prune_archives();
|
|
}
|
|
|
|
auto prune_archives() -> void {
|
|
if (options_.max_archives == 0) return;
|
|
while (archives_.size() > options_.max_archives) {
|
|
auto ignored = std::error_code{};
|
|
std::filesystem::remove(archives_.front(), ignored);
|
|
archives_.erase(archives_.begin());
|
|
}
|
|
}
|
|
|
|
std::filesystem::path path_;
|
|
file_options options_;
|
|
std::ofstream stream_;
|
|
std::size_t size_{0};
|
|
std::vector<std::filesystem::path> archives_;
|
|
};
|
|
|
|
/*
|
|
* <stacktrace> is not portable: libc++ has never implemented it, and only
|
|
* libstdc++ provides it here. Where it is missing, records still carry their
|
|
* call site through std::source_location - they simply carry no stack, and
|
|
* everything below degrades to an empty string rather than the module
|
|
* refusing to compile.
|
|
*
|
|
* CMake decides this and passes it in, rather than the module testing
|
|
* `__cpp_lib_stacktrace` itself: feature-test macros come from the standard
|
|
* library's headers, and `import std;` does not export them, so probing for
|
|
* one here silently reports "absent" even on libstdc++, which has it.
|
|
*/
|
|
#ifndef ENDERLOG_HAS_STACKTRACE
|
|
#define ENDERLOG_HAS_STACKTRACE 0
|
|
#endif
|
|
|
|
#if ENDERLOG_HAS_STACKTRACE
|
|
/** True when a frame belongs to the logging module itself. */
|
|
[[nodiscard]] inline auto is_logger_frame(const std::stacktrace_entry &entry) -> bool {
|
|
if (entry.description().find("ender::log") != std::string::npos) return true;
|
|
return entry.source_file().find("ender.log.cppm") != std::string::npos;
|
|
}
|
|
|
|
/**
|
|
* Render a trace as one indented line per frame.
|
|
*
|
|
* @param skip_logger_frames Drop leading frames belonging to this module, so
|
|
* the first reported frame is the caller. This is what makes the
|
|
* output stable across optimisation levels: in a release build the
|
|
* level wrappers are inlined into the caller, so counting frames
|
|
* alone would either over- or under-skip.
|
|
*/
|
|
[[nodiscard]] inline auto format_stacktrace(const std::stacktrace &trace,
|
|
const bool skip_logger_frames = true) -> std::string {
|
|
if (trace.empty()) return " <empty stacktrace>\n";
|
|
|
|
auto first = std::size_t{0};
|
|
if (skip_logger_frames) {
|
|
while (first < trace.size() && is_logger_frame(trace.at(first))) ++first;
|
|
if (first >= trace.size()) first = 0; // never hide the whole trace
|
|
}
|
|
|
|
auto text = std::string{};
|
|
for (auto index = first; index < trace.size(); ++index) {
|
|
const auto &entry = trace.at(index);
|
|
auto description = entry.description();
|
|
if (description.empty()) description = "<unknown>";
|
|
|
|
auto location = std::string{};
|
|
if (!entry.source_file().empty()) {
|
|
location = std::format(" ({}:{})", entry.source_file(), entry.source_line());
|
|
}
|
|
text += std::format(" #{:<3}{}{}\n", index - first, description, location);
|
|
}
|
|
return text;
|
|
}
|
|
|
|
/** Capture and render the current call stack, innermost frame first. */
|
|
[[nodiscard]] inline auto capture_stacktrace(const std::size_t skip = 2, const std::size_t depth = 16)
|
|
-> std::string {
|
|
return format_stacktrace(std::stacktrace::current(skip, depth));
|
|
}
|
|
#else
|
|
/**
|
|
* libc++ fallback: capture the current call stack with the platform's own
|
|
* backtrace API and render one indented line per frame.
|
|
*
|
|
* On Windows a frame is reported as `module.dll+0xRVA` (a MinGW release build
|
|
* has DWARF, not the PDB symbols dbghelp resolves, so a module+offset is the
|
|
* practical answer). On POSIX `backtrace_symbols` is used, which names a
|
|
* frame when the executable was linked with `-rdynamic`.
|
|
*/
|
|
#if defined(_WIN32)
|
|
[[nodiscard]] inline auto symbolicate_frame(void *address) -> std::string {
|
|
const auto value = reinterpret_cast<std::uintptr_t>(address);
|
|
HMODULE module = nullptr;
|
|
if (GetModuleHandleExW(GET_MODULE_HANDLE_EX_FLAG_FROM_ADDRESS | GET_MODULE_HANDLE_EX_FLAG_UNCHANGED_REFCOUNT,
|
|
reinterpret_cast<LPCWSTR>(address), &module)) {
|
|
wchar_t wide[260] = L"?";
|
|
GetModuleFileNameW(module, wide, 260U);
|
|
char narrow[260] = "?";
|
|
WideCharToMultiByte(CP_UTF8, 0, wide, -1, narrow, sizeof(narrow), nullptr, nullptr);
|
|
const char *base = std::strrchr(narrow, '\\');
|
|
return std::format("{}+0x{:X}", base != nullptr ? base + 1 : narrow, value - reinterpret_cast<std::uintptr_t>(module));
|
|
}
|
|
return std::format("0x{:X}", value);
|
|
}
|
|
#endif
|
|
|
|
[[nodiscard]] inline auto capture_stacktrace(const std::size_t skip = 2, const std::size_t depth = 16) -> std::string {
|
|
constexpr std::size_t max_frames = 64;
|
|
#if defined(_WIN32)
|
|
void *frames[max_frames] = {};
|
|
const auto want = static_cast<DWORD>(std::min(max_frames, skip + std::max<std::size_t>(depth, 1U)));
|
|
const USHORT count = CaptureStackBackTrace(static_cast<DWORD>(skip), want, frames, nullptr);
|
|
auto text = std::string{};
|
|
for (USHORT index = 0; index < count; ++index) {
|
|
text += std::format(" #{:<3}{}\n", index, symbolicate_frame(frames[index]));
|
|
}
|
|
return text;
|
|
#elif (defined(__unix__) || defined(__APPLE__)) && !defined(__EMSCRIPTEN__)
|
|
void *frames[max_frames] = {};
|
|
const int count = ::backtrace(frames, static_cast<int>(std::min(max_frames, skip + std::max<std::size_t>(depth, 1U))));
|
|
char **symbols = ::backtrace_symbols(frames, count);
|
|
auto text = std::string{};
|
|
for (int index = static_cast<int>(std::min<std::size_t>(skip, static_cast<std::size_t>(count))); index < count; ++index) {
|
|
text += std::format(" #{:<3}{}\n", index - static_cast<int>(skip),
|
|
symbols != nullptr ? symbols[index] : std::format("0x{:X}", reinterpret_cast<std::uintptr_t>(frames[index])));
|
|
}
|
|
if (symbols != nullptr) std::free(symbols);
|
|
return text;
|
|
#else
|
|
(void) skip;
|
|
(void) depth;
|
|
return {};
|
|
#endif
|
|
}
|
|
#endif
|
|
|
|
/**
|
|
* The process-wide logger.
|
|
*
|
|
* `enabled` is an atomic read so hot paths can guard expensive message
|
|
* construction; everything else takes the mutex.
|
|
*/
|
|
class logger {
|
|
public:
|
|
[[nodiscard]] static auto instance() -> logger & {
|
|
static logger shared;
|
|
return shared;
|
|
}
|
|
|
|
auto configure(const options &config) -> void {
|
|
const auto lock = std::scoped_lock{mutex_};
|
|
options_ = config;
|
|
minimum_.store(static_cast<std::uint8_t>(config.minimum), std::memory_order_relaxed);
|
|
}
|
|
|
|
[[nodiscard]] auto configuration() const -> options {
|
|
const auto lock = std::scoped_lock{mutex_};
|
|
return options_;
|
|
}
|
|
|
|
[[nodiscard]] auto enabled(const level severity) const -> bool {
|
|
return static_cast<std::uint8_t>(severity) >= minimum_.load(std::memory_order_relaxed);
|
|
}
|
|
|
|
auto add_sink(std::shared_ptr<sink> destination) -> void {
|
|
const auto lock = std::scoped_lock{mutex_};
|
|
sinks_.push_back(std::move(destination));
|
|
}
|
|
|
|
auto set_sinks(std::vector<std::shared_ptr<sink>> destinations) -> void {
|
|
const auto lock = std::scoped_lock{mutex_};
|
|
sinks_ = std::move(destinations);
|
|
}
|
|
|
|
auto dispatch(const record &entry) -> void {
|
|
const auto lock = std::scoped_lock{mutex_};
|
|
for (const auto &destination: sinks_) {
|
|
destination->write(entry);
|
|
}
|
|
}
|
|
|
|
private:
|
|
logger() { sinks_.push_back(std::make_shared<console_sink>()); }
|
|
|
|
mutable std::mutex mutex_;
|
|
options options_{};
|
|
std::atomic<std::uint8_t> minimum_{static_cast<std::uint8_t>(options{}.minimum)};
|
|
std::vector<std::shared_ptr<sink>> sinks_;
|
|
};
|
|
|
|
/** Apply a configuration to the process-wide logger. */
|
|
inline auto configure(const options &config) -> void { logger::instance().configure(config); }
|
|
|
|
/** Current configuration of the process-wide logger. */
|
|
[[nodiscard]] inline auto current_options() -> options { return logger::instance().configuration(); }
|
|
|
|
/** Route records to an additional sink. */
|
|
inline auto add_sink(std::shared_ptr<sink> destination) -> void {
|
|
logger::instance().add_sink(std::move(destination));
|
|
}
|
|
|
|
/**
|
|
* Create a file sink, route records to it, and hand it back.
|
|
*
|
|
* The previous log at `path` is archived on open, so this never appends onto
|
|
* an earlier run.
|
|
*
|
|
* @return The sink, so the caller can inspect the archives it creates.
|
|
*/
|
|
inline auto add_file_sink(std::filesystem::path path, const file_options &options = {})
|
|
-> std::shared_ptr<file_sink> {
|
|
auto destination = std::make_shared<file_sink>(std::move(path), options);
|
|
logger::instance().add_sink(destination);
|
|
return destination;
|
|
}
|
|
|
|
/** Replace every sink. */
|
|
inline auto set_sinks(std::vector<std::shared_ptr<sink>> destinations) -> void {
|
|
logger::instance().set_sinks(std::move(destinations));
|
|
}
|
|
|
|
/** True when a record at this level would be emitted. */
|
|
[[nodiscard]] inline auto enabled(const level severity) -> bool { return logger::instance().enabled(severity); }
|
|
|
|
namespace detail {
|
|
/** Build and dispatch one record. Not for direct use. */
|
|
inline auto emit(const level severity, std::string message, const std::source_location location) -> void {
|
|
auto &target = logger::instance();
|
|
if (!target.enabled(severity)) return;
|
|
|
|
const auto config = target.configuration();
|
|
auto entry = record{
|
|
.severity = severity,
|
|
.message = std::move(message),
|
|
.file = location.file_name(),
|
|
.line = static_cast<std::uint32_t>(location.line()),
|
|
.function = location.function_name(),
|
|
.time = std::chrono::system_clock::now(),
|
|
.thread = std::this_thread::get_id(),
|
|
};
|
|
if (severity >= config.stacktrace_from) {
|
|
entry.stacktrace = capture_stacktrace(config.stacktrace_skip, config.stacktrace_depth);
|
|
}
|
|
target.dispatch(entry);
|
|
}
|
|
}
|
|
|
|
/**
|
|
* Emit a record.
|
|
*
|
|
* The source location defaults to the call site, so this reports exactly
|
|
* where it was called from.
|
|
*/
|
|
inline auto log(const level severity,
|
|
std::string message,
|
|
const std::source_location location = std::source_location::current()) -> void {
|
|
detail::emit(severity, std::move(message), location);
|
|
}
|
|
|
|
inline auto trace(std::string message, const std::source_location location = std::source_location::current())
|
|
-> void {
|
|
detail::emit(level::trace, std::move(message), location);
|
|
}
|
|
|
|
inline auto debug(std::string message, const std::source_location location = std::source_location::current())
|
|
-> void {
|
|
detail::emit(level::debug, std::move(message), location);
|
|
}
|
|
|
|
inline auto info(std::string message, const std::source_location location = std::source_location::current())
|
|
-> void {
|
|
detail::emit(level::info, std::move(message), location);
|
|
}
|
|
|
|
inline auto warn(std::string message, const std::source_location location = std::source_location::current())
|
|
-> void {
|
|
detail::emit(level::warn, std::move(message), location);
|
|
}
|
|
|
|
/** Emits at `error`, which captures a call stack by default. */
|
|
inline auto error(std::string message, const std::source_location location = std::source_location::current())
|
|
-> void {
|
|
detail::emit(level::error, std::move(message), location);
|
|
}
|
|
|
|
inline auto critical(std::string message, const std::source_location location = std::source_location::current())
|
|
-> void {
|
|
detail::emit(level::critical, std::move(message), location);
|
|
}
|
|
}
|