Keep a log file, so a tower's record outlives the tmux session

This commit is contained in:
pgdalmeida 2026-09-22 18:15:09 +02:00
parent 943f978a73
commit 582047d3a2
Signed by: pedro.almeida
GPG Key ID: D4A6C394DF13F1D7
14 changed files with 940 additions and 18 deletions

View File

@ -66,6 +66,7 @@ add_library(fgc_core STATIC
src/core/TmcCurrent.cpp src/core/TmcCurrent.cpp
src/core/HardwarePresence.cpp src/core/HardwarePresence.cpp
src/core/HardwareChecks.cpp src/core/HardwareChecks.cpp
src/core/FileLogSink.cpp
src/core/AxisSpeed.cpp src/core/AxisSpeed.cpp
src/core/FirmwareConfig.cpp src/core/FirmwareConfig.cpp
src/core/ScanGrid.cpp src/core/ScanGrid.cpp

View File

@ -310,9 +310,32 @@ enable_tui = false
[Logging] [Logging]
; level: trace|debug|info|warn|error|off (default info). --log-level overrides. ; level: trace|debug|info|warn|error|off (default info). --log-level overrides.
; This is the CONSOLE level only. The log file below has its own, so `off` here
; quietens the screen and the tower keeps recording; --no-log-file stops that.
level = info level = info
; Verbatim per-category wire tracing, independent of the level above. Comma list ; Verbatim per-category wire tracing, independent of the level above. Comma list
; of: serial, mqtt, camera, control, all, none. OFF by default. --trace overrides. ; of: serial, mqtt, camera, control, all, none. OFF by default. --trace overrides.
; Lines are tagged [SERIAL]/[MQTT]/[CAMERA]/[CONTROL] with TX/RX direction, e.g. ; Lines are tagged [SERIAL]/[MQTT]/[CAMERA]/[CONTROL] with TX/RX direction, e.g.
; [SERIAL] TX kd180 / [SERIAL] RX $;1234;0;... ; [SERIAL] TX kd180 / [SERIAL] RX $;1234;0;...
;
; NOTE this also governs what reaches the LOG FILE. The serial trace is ~4 ST
; lines a second, taking steady-state logging from ~5 MB/day to ~41 MB/day -
; enough to churn the whole retained window in a couple of days and age out the
; startup record. Turn it on to chase a problem, off again afterwards.
trace = trace =
; --- the persistent log file ------------------------------------------------
; A tower runs detached for days, and in TUI mode every line goes to a 500-line
; on-screen ring buffer and nowhere else - so the record dies with the session.
; This is that record: <data dir>/logs/fgc_<stamp>.<NNN>.log, beside the test and
; diag reports.
file = true
; The file is normally MORE verbose than the console: a readable dashboard, a
; detailed file. Independent of `level` above.
file_level = debug
; Bounded at file_keep x file_max_mb (200 MB here). A new file per run, rotated
; by size within it, oldest pruned. Steady state is ~5 MB/day.
file_max_mb = 20
file_keep = 10
; Where to put them. Empty => the data log dir, alongside test_*/diag_* reports.
file_dir =

View File

@ -63,8 +63,13 @@ Parsed and validated by `ConfigLoader` ([src/core/Config.cpp](../src/core/Config
| `Env` | `i2c_device` | string | `/dev/i2c-1` | SHT41 I2C bus device (see `[Env]` note); required when `enable_env` | | `Env` | `i2c_device` | string | `/dev/i2c-1` | SHT41 I2C bus device (see `[Env]` note); required when `enable_env` |
| `Env` | `i2c_addr` | int | `68` (`0x44`) | SHT41 I2C slave address; decimal or `0x`-prefixed hex | | `Env` | `i2c_addr` | int | `68` (`0x44`) | SHT41 I2C slave address; decimal or `0x`-prefixed hex |
| `Env` | `period_ms` | int | `2000` | Sample interval | | `Env` | `period_ms` | int | `2000` | Sample interval |
| `Logging` | `level` | enum | `info` | Linear log level (`--log-level` overrides) | | `Logging` | `level` | enum | `info` | **Console** log level (`--log-level` overrides). Does **not** silence the log file, which has its own |
| `Logging` | `trace` | csv | — | Wire-trace categories, off by default (`--trace` overrides) | | `Logging` | `trace` | csv | — | Wire-trace categories, off by default (`--trace` overrides) |
| `Logging` | `file` | bool | `true` | Write a persistent log file (`--no-log-file` overrides) |
| `Logging` | `file_level` | enum | `debug` | **File** log level, independent of `level` (`--log-file-level` overrides) |
| `Logging` | `file_max_mb` | int | `20` | Rotate past this size. Clamped to 1..1024 |
| `Logging` | `file_keep` | int | `10` | How many `fgc_*.log` to retain, oldest deleted. Clamped to 1..100 |
| `Logging` | `file_dir` | path | — | Defaults to the data log dir alongside the test and diag reports |
| `UI` | `enable_tui` | bool | `false` | Full-screen terminal dashboard (`--tui`/`--no-tui` override; needs `WITH_TUI=ON`) | | `UI` | `enable_tui` | bool | `false` | Full-screen terminal dashboard (`--tui`/`--no-tui` override; needs `WITH_TUI=ON`) |
| `Motor` | `yaw_counts_per_deg` / `pitch_counts_per_deg` | float | `983.33` / — | Encoder counts per degree (**calibrate**; may be negative to flip) | | `Motor` | `yaw_counts_per_deg` / `pitch_counts_per_deg` | float | `983.33` / — | Encoder counts per degree (**calibrate**; may be negative to flip) |
| `Motor` | `yaw_center_count` / `pitch_center_count` | int | `500000` | Count homing **defines** as the middle of the found travel. **Must exceed half the travel**, or the negative end falls below zero — the `500000` default suits the Delta's ~89k half-travel, not a geared-up rig (the IOTA needs 1000000). A warning names it after each home | | `Motor` | `yaw_center_count` / `pitch_center_count` | int | `500000` | Count homing **defines** as the middle of the found travel. **Must exceed half the travel**, or the negative end falls below zero — the `500000` default suits the Delta's ~89k half-travel, not a geared-up rig (the IOTA needs 1000000). A warning names it after each home |
@ -468,6 +473,39 @@ what is missing — worded so it cannot be mistaken for a normal startup line.
falling back to the config file. Keep credentials out of `config.ini` (which is gitignored anyway) by exporting falling back to the config file. Keep credentials out of `config.ini` (which is gitignored anyway) by exporting
them or using a systemd `EnvironmentFile`. them or using a systemd `EnvironmentFile`.
### The log file
A tower runs detached for days inside a tmux session, and in TUI mode every log
line goes into a 500-line on-screen ring buffer and **nowhere else** — so the
record of what it did dies with the session. The one moment you want it, "why is
this axis not moving?", is exactly when it is gone.
So the program also writes `~/.local/share/fire_gimbal_control/logs/fgc_<stamp>.<NNN>.log`,
alongside the existing `test_*`, `diag_*` and `pitch_setup_*` reports. On by
default.
**The file is deliberately more verbose than the console.** `level` governs the
dashboard, `file_level` the file, and the two are independent — the default pair
is a readable `info` on screen and a detailed `debug` on disk. Consequently
`--log-level off` quietens the *console* and the tower keeps recording; use
`--no-log-file` to stop writing.
**Wire traces reach the file only when `trace` turns them on**, for both outputs
at once. That gating is not cosmetic: the serial trace alone is about 4 `ST`
lines per second, so steady-state logging goes from roughly **5 MB/day to
41 MB/day** — enough to churn through the whole retained window in a couple of
days and age out the startup record you may also have wanted.
A new file is started per run and rotated by size within it, oldest pruned by
count, so the footprint is bounded at `file_keep × file_max_mb` (200 MB by
default). Each file opens with a header naming the build, tower, PID, config and
hardware paths and the full command line, re-emitted after every rotation so an
archive found on its own is still self-describing. Lines carry a `YYYY-MM-DD`
prefix the console ones do not, because a file may span days.
> Failures before the config is read — bad arguments, no `config.ini` found —
> happen before the log's own path is knowable and stay console-only.
## Command-line flags ## Command-line flags
Parsed by Boost.Program_options ([main.cpp](../main.cpp)). Flags override `[Features]`. Parsed by Boost.Program_options ([main.cpp](../main.cpp)). Flags override `[Features]`.
@ -486,7 +524,9 @@ Parsed by Boost.Program_options ([main.cpp](../main.cpp)). Flags override `[Feat
| `--degraded` | Start even though declared hardware is missing (field triage; overrides `strict_presence` and says so loudly in the log) | | `--degraded` | Start even though declared hardware is missing (field triage; overrides `strict_presence` and says so loudly in the log) |
| `--tui` | Show the full-screen terminal dashboard (overrides `[UI] enable_tui`) | | `--tui` | Show the full-screen terminal dashboard (overrides `[UI] enable_tui`) |
| `--no-tui` | Force the headless line console (overrides config; wins over `--tui`) | | `--no-tui` | Force the headless line console (overrides config; wins over `--tui`) |
| `--log-level <lvl>` | `trace`/`debug`/`info`/`warn`/`error`/`off` | | `--log-level <lvl>` | **Console** level: `trace`/`debug`/`info`/`warn`/`error`/`off`. Does not silence the log file |
| `--no-log-file` | Do not write a persistent log file this run |
| `--log-file-level <lvl>` | File level, independent of `--log-level` (default `debug`) |
| `--trace <cats>` | Verbatim wire trace; comma list `serial,mqtt,camera,control,all,none` | | `--trace <cats>` | Verbatim wire trace; comma list `serial,mqtt,camera,control,all,none` |
Typical headless dev run: `scripts/run.sh --mock-serial --mock-camera --no-mqtt --start`. Typical headless dev run: `scripts/run.sh --mock-serial --mock-camera --no-mqtt --start`.

View File

@ -9,6 +9,7 @@ Per-file reference for the refactored tree, plus the shared data structures.
| [include/fgc/Config.h](../include/fgc/Config.h), [src/core/Config.cpp](../src/core/Config.cpp) | Typed `AppConfig` (General/Network/Serial/Camera/Paths/Features/Logging/UI/Motor/Scan/**IMU**) + `ConfigLoader` (INI parse, env overrides, validation) | | [include/fgc/Config.h](../include/fgc/Config.h), [src/core/Config.cpp](../src/core/Config.cpp) | Typed `AppConfig` (General/Network/Serial/Camera/Paths/Features/Logging/UI/Motor/Scan/**IMU**) + `ConfigLoader` (INI parse, env overrides, validation) |
| [include/fgc/Paths.h](../include/fgc/Paths.h), [src/core/Paths.cpp](../src/core/Paths.cpp) | `~`/`$ENV` expansion, executable dir, config search order, default output dir | | [include/fgc/Paths.h](../include/fgc/Paths.h), [src/core/Paths.cpp](../src/core/Paths.cpp) | `~`/`$ENV` expansion, executable dir, config search order, default output dir |
| [include/fgc/Logger.h](../include/fgc/Logger.h), [src/core/Logger.cpp](../src/core/Logger.cpp) | Leveled, thread-safe logger + per-category wire trace; `LOG_TRACE..LOG_ERROR`, `LOG_TRACE_CAT` | | [include/fgc/Logger.h](../include/fgc/Logger.h), [src/core/Logger.cpp](../src/core/Logger.cpp) | Leveled, thread-safe logger + per-category wire trace; `LOG_TRACE..LOG_ERROR`, `LOG_TRACE_CAT` |
| [include/fgc/FileLogSink.h](../include/fgc/FileLogSink.h), [src/core/FileLogSink.cpp](../src/core/FileLogSink.cpp) | The persistent log file: append, size rotation, count-based pruning, a self-describing header per file. Runs inside `Logger`'s non-recursive lock, so it never logs - failures latch into `failed()`/`lastError()` for the caller to report |
| [include/fgc/Geometry.h](../include/fgc/Geometry.h), [src/core/Geometry.cpp](../src/core/Geometry.cpp) | Per-axis degrees↔encoder-counts affine map (`[Motor]` calibration) | | [include/fgc/Geometry.h](../include/fgc/Geometry.h), [src/core/Geometry.cpp](../src/core/Geometry.cpp) | Per-axis degrees↔encoder-counts affine map (`[Motor]` calibration) |
| [include/fgc/ScanGrid.h](../include/fgc/ScanGrid.h), [src/core/ScanGrid.cpp](../src/core/ScanGrid.cpp) | Capture waypoints (CSV or generated) + one-way wrapping cursor (`[Scan]`) | | [include/fgc/ScanGrid.h](../include/fgc/ScanGrid.h), [src/core/ScanGrid.cpp](../src/core/ScanGrid.cpp) | Capture waypoints (CSV or generated) + one-way wrapping cursor (`[Scan]`) |
| [include/fgc/TelemetryParser.h](../include/fgc/TelemetryParser.h), [src/core/TelemetryParser.cpp](../src/core/TelemetryParser.cpp) | `parseTelemetryLine` (firmware `ST` line) → `std::optional<MotorTelemetry>` | | [include/fgc/TelemetryParser.h](../include/fgc/TelemetryParser.h), [src/core/TelemetryParser.cpp](../src/core/TelemetryParser.cpp) | `parseTelemetryLine` (firmware `ST` line) → `std::optional<MotorTelemetry>` |

View File

@ -273,6 +273,19 @@ struct EnvConfig {
struct LoggingConfig { struct LoggingConfig {
std::string level; // trace|debug|info|warn|error|off; empty => default (CLI overrides) std::string level; // trace|debug|info|warn|error|off; empty => default (CLI overrides)
std::string trace; // verbatim wire-trace categories: serial,mqtt,camera,control,all,none std::string trace; // verbatim wire-trace categories: serial,mqtt,camera,control,all,none
// Persistent log file. A tower runs detached for days and, in TUI mode,
// every line goes to a 500-line on-screen ring buffer and nowhere else - so
// the record of what it did dies with the session. This is that record.
//
// Deliberately INDEPENDENT of `level` above: the dashboard stays readable at
// info while the file keeps debug. Wire traces reach the file only when
// `trace` turns them on, because the serial trace alone is ~4 lines/second.
bool file = true; // written unless turned off
std::string file_level; // empty => "debug"
int file_max_mb = 20; // rotate past this
int file_keep = 10; // fgc_*.log retained, oldest deleted
std::string file_dir; // empty => paths::defaultLogDir()
}; };
struct UiConfig { struct UiConfig {

98
include/fgc/FileLogSink.h Normal file
View File

@ -0,0 +1,98 @@
#pragma once
#include "fgc/Logger.h"
#include <cstdio>
#include <string>
#include <vector>
namespace fgc {
// A rotating, size-capped log file for the tower's own operation.
//
// A tower runs detached for days inside a tmux session, and in TUI mode every
// log line goes into a 500-line ring buffer on screen and nowhere else - so the
// record of what it did dies with the session. That is the one thing you want
// when somebody asks why an axis is not moving.
//
// This is deliberately a plain appender rather than anything clever:
//
// * It runs INSIDE Logger's lock. Logger holds a non-recursive mutex while it
// calls the sink, so every method here MUST be free of LOG_* - one logging
// call from this file deadlocks the whole process. Failures are recorded and
// reported through failed()/lastError(), which the caller polls from OUTSIDE
// the lock. That constraint is why paths::writeLogFile() is not reused: it
// LOG_WARNs on failure, and it truncates rather than appends.
// * It flushes every line but never fsyncs. A crashed process keeps everything
// (the bytes are already in the page cache); only a power cut loses the tail.
// fsync per line on a tower's eMMC would be far worse than that trade.
// * Rotation is by size, checked before each write. Files are pruned by count,
// oldest first.
struct FileLogPolicy {
// Empty => paths::defaultLogDir().
std::string dir;
// Rotate once a write would push the file past this. 0 disables rotation.
long long max_bytes = 20LL * 1024 * 1024;
// How many <prefix>_*.log to keep in `dir`, counting every run's files and
// every rotation of them. Oldest are deleted. 0 disables pruning.
int keep_files = 10;
// File name prefix. Deliberately NOT "test": Application::latestPriorTestReport()
// scans this same directory for test_*.log and would otherwise pick up ours.
std::string prefix = "fgc";
};
class FileLogSink {
public:
FileLogSink() = default;
~FileLogSink();
FileLogSink(const FileLogSink&) = delete;
FileLogSink& operator=(const FileLogSink&) = delete;
// Create the directory if needed and open a fresh file for this run. `header`
// is written first and re-written after every rotation, so each file on disk
// says for itself which build and tower produced it. Returns false and sets
// failed() if the file cannot be opened.
bool open(const FileLogPolicy& policy, const std::string& header);
// Append one already-formatted Logger line (no trailing newline, and it
// begins "HH:MM:SS.mmm"). A date is prepended here rather than in Logger,
// because the on-screen panes are width-constrained and a file that may span
// days is the only place the date is actually needed.
//
// `cat` distinguishes a wire-trace line from an ordinary one; the caller uses
// it to decide routing, and it is recorded here only for completeness.
// Never throws, never logs. A no-op once failed().
void write(LogLevel level, LogCat cat, const std::string& line);
void close();
bool isOpen() const { return fp_ != nullptr; }
std::string path() const { return path_; }
// Set when an open, write or rotate failed. The sink then stops writing
// rather than retrying every line. Poll this from outside Logger's lock.
bool failed() const { return failed_; }
std::string lastError() const { return last_error_; }
// Exposed for tests: the files this policy would prune, newest first.
static std::vector<std::string> existingFiles(const FileLogPolicy& policy);
private:
std::string segmentPath(int n) const;
bool openFile(const std::string& path);
void rotate();
void prune();
void fail(const std::string& what);
std::FILE* fp_ = nullptr;
FileLogPolicy policy_;
std::string header_;
std::string path_;
std::string base_; // path without the ".<NNN>.log" suffix
long long bytes_ = 0;
long long lines_ = 0; // lines in the CURRENT file; guards rotation loops
int rotation_ = 0;
bool failed_ = false;
std::string last_error_;
};
} // namespace fgc

View File

@ -30,6 +30,9 @@ enum class LogCat : unsigned {
// Lines at Warn/Error go to stderr; everything else to stdout. // Lines at Warn/Error go to stderr; everything else to stdout.
class Logger { class Logger {
public: public:
// The CONSOLE threshold. Kept as the plain name because every existing
// caller - `--log-level`, [Logging] level, the `debug` console command -
// means the console. See setFileLevel() for the file's own.
static void setLevel(LogLevel level); static void setLevel(LogLevel level);
static LogLevel level(); static LogLevel level();
static bool enabled(LogLevel level); static bool enabled(LogLevel level);
@ -62,6 +65,37 @@ public:
// function to restore the default writer. Thread-safe. // function to restore the default writer. Thread-safe.
using LogSink = std::function<void(LogLevel level, const std::string& line)>; using LogSink = std::function<void(LogLevel level, const std::string& line)>;
static void setSink(LogSink sink); static void setSink(LogSink sink);
// --- persistent file logging ------------------------------------------
//
// A SECOND, independent sink slot. setSink() above belongs to the TUI, which
// installs its pane writer on start and clears it on stop; a file sink put
// through that one slot would be silently replaced, and the shutdown lines -
// logged after ui->stop() - are exactly the ones worth keeping.
//
// It takes the CATEGORY as well as the level. A wire-trace line arrives with
// level == Trace and is otherwise indistinguishable from a plain LOG_TRACE,
// and the file has to tell them apart to honour "traces only when asked for".
//
// WARNING: the sink runs while this logger's mutex is held, and that mutex is
// NOT recursive. A sink that calls LOG_* deadlocks the process - including
// the control loop, possibly mid-move. Sinks must report failure by latching
// a flag the caller polls, never by logging.
using FileSink = std::function<void(LogLevel level, LogCat cat, const std::string& line)>;
static void setFileSink(FileSink sink);
// The file's own threshold, independent of the console's, so the dashboard
// can stay at info while the file keeps debug.
//
// The LOG_* macros gate on the MORE verbose of the two, and each sink then
// filters to its own. Off (the default) means the file wants nothing, which
// leaves every existing path byte-for-byte as it was.
static void setFileLevel(LogLevel level);
static LogLevel fileLevel();
static bool setFileLevelFromString(const std::string& s);
// min(level(), fileLevel()) - what the macros actually gate on.
static LogLevel effectiveLevel();
}; };
// RAII helper that buffers one log line and flushes it on commit(). // RAII helper that buffers one log line and flushes it on commit().

View File

@ -1,16 +1,45 @@
#include "fgc/Application.h" #include "fgc/Application.h"
#include "fgc/Config.h" #include "fgc/Config.h"
#include "fgc/FileLogSink.h"
#include "fgc/Logger.h" #include "fgc/Logger.h"
#include "fgc/Paths.h" #include "fgc/Paths.h"
#include "fgc/SingleInstance.h" #include "fgc/SingleInstance.h"
#include <iostream> #include <iostream>
#include <sstream>
#include <unistd.h>
#include <boost/program_options.hpp> #include <boost/program_options.hpp>
namespace po = boost::program_options; namespace po = boost::program_options;
using namespace fgc; using namespace fgc;
namespace {
std::string want_or(const std::string& s, const char* fallback) {
return s.empty() ? std::string(fallback) : s;
}
// Written at the top of every log file, and again after each rotation, so an
// archive found on its own still says which build and tower produced it.
std::string fileLogHeader(const fgc::AppConfig& cfg, const std::string& cfg_path,
const std::string& hw_path, int argc, char* argv[]) {
std::ostringstream h;
h << "=== fire_gimbal_control ===\n";
h << "build " << FGC_GIT_REV << "\n";
h << "tower " << cfg.general.tower_name << "\n";
h << "pid " << ::getpid() << "\n";
h << "config " << cfg_path << "\n";
h << "hardware " << (hw_path.empty() ? "(none)" : hw_path) << "\n";
h << "argv ";
for (int i = 0; i < argc; ++i) h << ' ' << argv[i];
h << "\n===";
return h.str();
}
} // namespace
int main(int argc, char* argv[]) { int main(int argc, char* argv[]) {
po::options_description desc("Fire Gimbal Control options"); po::options_description desc("Fire Gimbal Control options");
desc.add_options() desc.add_options()
@ -35,7 +64,12 @@ int main(int argc, char* argv[]) {
("no-lock", po::bool_switch(), ("no-lock", po::bool_switch(),
"skip the single-instance lock (dev only: for a second mock-only instance)") "skip the single-instance lock (dev only: for a second mock-only instance)")
("lock-file", po::value<std::string>(), "path to the single-instance lockfile") ("lock-file", po::value<std::string>(), "path to the single-instance lockfile")
("log-level", po::value<std::string>(), "trace|debug|info|warn|error|off") ("log-level", po::value<std::string>(),
"console verbosity: trace|debug|info|warn|error|off. Does NOT silence the log "
"file, which has its own level")
("no-log-file", po::bool_switch(), "do not write a persistent log file this run")
("log-file-level", po::value<std::string>(),
"log-file verbosity, independent of --log-level (default debug)")
("trace", po::value<std::string>(), ("trace", po::value<std::string>(),
"verbatim wire trace, comma list: serial,mqtt,camera,control,all,none"); "verbatim wire trace, comma list: serial,mqtt,camera,control,all,none");
@ -73,6 +107,12 @@ int main(int argc, char* argv[]) {
return 1; return 1;
} }
// Resolved before the config is even loaded, because the install block below
// needs them and it runs before Application::run() touches its own options.
const std::string opts_log_file_level =
vm.count("log-file-level") ? vm["log-file-level"].as<std::string>() : std::string();
const bool opts_no_log_file = vm["no-log-file"].as<bool>();
AppConfig cfg; AppConfig cfg;
try { try {
cfg = ConfigLoader::loadFromFile(*cfg_path, hw_path.value_or("")); cfg = ConfigLoader::loadFromFile(*cfg_path, hw_path.value_or(""));
@ -80,6 +120,54 @@ int main(int argc, char* argv[]) {
std::cerr << "Config error (" << *cfg_path << "): " << e.what() << "\n"; std::cerr << "Config error (" << *cfg_path << "): " << e.what() << "\n";
return 1; return 1;
} }
// Start the persistent log HERE - before the first LOG_INFO below, and well
// before Application::run().
//
// Two reasons it cannot wait: run() can refuse to start at
// reconcileHardware() and return before the UI exists, so a sink installed
// there would miss the very message explaining why the tower did not come
// up; and in TUI mode every line otherwise lands in a 500-line on-screen
// ring buffer that dies with the tmux session.
//
// Anything logged earlier than this (bad arguments, no config.ini found)
// happens before the log's own path is knowable, and stays console-only.
FileLogSink file_log;
if (cfg.logging.file && !opts_no_log_file) {
FileLogPolicy pol;
pol.dir = cfg.logging.file_dir;
pol.max_bytes = static_cast<long long>(cfg.logging.file_max_mb) * 1024 * 1024;
pol.keep_files = cfg.logging.file_keep;
LogLevel flvl = LogLevel::Debug; // the file is normally more verbose
const std::string want =
!opts_log_file_level.empty() ? opts_log_file_level : cfg.logging.file_level;
bool bad_level = false;
if (!want.empty()) {
LogLevel parsed{};
if (Logger::setFileLevelFromString(want)) parsed = Logger::fileLevel();
else bad_level = true;
if (!bad_level) flvl = parsed;
}
Logger::setFileLevel(flvl);
if (file_log.open(pol, fileLogHeader(cfg, *cfg_path, hw_path.value_or(""), argc, argv))) {
Logger::setFileSink([&file_log](LogLevel l, LogCat c, const std::string& line) {
file_log.write(l, c, line);
});
}
// Reported from OUT HERE, never from inside the sink: the sink runs
// under Logger's non-recursive mutex and logging from it deadlocks.
if (file_log.failed()) {
Logger::setFileLevel(LogLevel::Off);
LOG_WARN << "no log file: " << file_log.lastError();
} else {
LOG_INFO << "logging to " << file_log.path() << " (level "
<< want_or(want, "debug") << ", " << cfg.logging.file_keep << " x "
<< cfg.logging.file_max_mb << " MB)";
}
if (bad_level) LOG_WARN << "unknown Logging.file_level '" << want << "', using debug";
}
LOG_INFO << "Loaded config: " << *cfg_path; LOG_INFO << "Loaded config: " << *cfg_path;
// Only one instance may run: a second would fight the first over the motor's // Only one instance may run: a second would fight the first over the motor's

View File

@ -431,6 +431,18 @@ AppConfig ConfigLoader::fromMap(const std::map<std::string, std::string>& kv) {
cfg.logging.level = get(kv, "Logging.level", cfg.logging.level); cfg.logging.level = get(kv, "Logging.level", cfg.logging.level);
cfg.logging.trace = get(kv, "Logging.trace", cfg.logging.trace); cfg.logging.trace = get(kv, "Logging.trace", cfg.logging.trace);
cfg.logging.file = getBool(kv, "Logging.file", cfg.logging.file);
cfg.logging.file_level = get(kv, "Logging.file_level", cfg.logging.file_level);
cfg.logging.file_max_mb = getInt(kv, "Logging.file_max_mb", cfg.logging.file_max_mb);
cfg.logging.file_keep = getInt(kv, "Logging.file_keep", cfg.logging.file_keep);
cfg.logging.file_dir = get(kv, "Logging.file_dir", cfg.logging.file_dir);
// Clamp rather than refuse: a silly retention value should not stop a tower
// starting, but it must not be obeyed either. A max_mb under 1 would rotate
// on almost every line.
if (cfg.logging.file_max_mb < 1) cfg.logging.file_max_mb = 1;
if (cfg.logging.file_max_mb > 1024) cfg.logging.file_max_mb = 1024;
if (cfg.logging.file_keep < 1) cfg.logging.file_keep = 1;
if (cfg.logging.file_keep > 100) cfg.logging.file_keep = 100;
cfg.ui.enable_tui = getBool(kv, "UI.enable_tui", cfg.ui.enable_tui); cfg.ui.enable_tui = getBool(kv, "UI.enable_tui", cfg.ui.enable_tui);

214
src/core/FileLogSink.cpp Normal file
View File

@ -0,0 +1,214 @@
#include "fgc/FileLogSink.h"
#include "fgc/Paths.h"
#include <algorithm>
#include <chrono>
#include <cstring>
#include <ctime>
#include <filesystem>
#include <system_error>
// NOTE: no "fgc/Logger.h" logging in this file, by design. Logger calls this
// sink while holding a non-recursive mutex, so a LOG_* from here deadlocks the
// process. Errors go to failed()/lastError() for the caller to report.
namespace fgc {
namespace {
namespace fs = std::filesystem;
// "YYYY-MM-DD ", prepended to each line. Logger's own stamp is HH:MM:SS.mmm with
// no date, which is fine on screen and ambiguous in a file that may span days.
std::string today() {
const auto t = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
std::tm tm{};
localtime_r(&t, &tm);
char buf[16];
std::strftime(buf, sizeof(buf), "%Y-%m-%d ", &tm);
return buf;
}
// "YYYYMMDD-HHMMSS", matching paths::timestampedLogName()'s stamp so every file
// in the log dir sorts the same way regardless of which writer made it.
std::string runStamp() {
const auto t = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
std::tm tm{};
localtime_r(&t, &tm);
char buf[32];
std::strftime(buf, sizeof(buf), "%Y%m%d-%H%M%S", &tm);
return buf;
}
std::string dirOf(const FileLogPolicy& p) {
return p.dir.empty() ? paths::defaultLogDir() : p.dir;
}
} // namespace
FileLogSink::~FileLogSink() { close(); }
std::vector<std::string> FileLogSink::existingFiles(const FileLogPolicy& policy) {
std::vector<std::string> out;
std::error_code ec;
const fs::path dir = dirOf(policy);
if (!fs::exists(dir, ec)) return out;
const std::string want = policy.prefix + "_";
for (const auto& e : fs::directory_iterator(dir, ec)) {
if (ec) break;
if (!e.is_regular_file(ec)) continue;
const std::string name = e.path().filename().string();
if (name.rfind(want, 0) != 0) continue;
if (name.size() < 4 || name.substr(name.size() - 4) != ".log") continue;
out.push_back(e.path().string());
}
// Names embed YYYYMMDD-HHMMSS, so lexicographic order is chronological.
// Newest first.
std::sort(out.begin(), out.end(), std::greater<std::string>());
return out;
}
bool FileLogSink::open(const FileLogPolicy& policy, const std::string& header) {
close();
policy_ = policy;
header_ = header;
failed_ = false;
last_error_.clear();
rotation_ = 0;
std::error_code ec;
fs::create_directories(dirOf(policy_), ec);
if (ec) {
fail("cannot create " + dirOf(policy_) + ": " + ec.message());
return false;
}
// "<dir>/<prefix>_<stamp>"; the segment number and ".log" are appended by
// segmentPath(). paths::timestampedLogName() is not reused: it bakes in the
// ".log", and the segment has to sit BEFORE the extension.
base_ = (fs::path(dirOf(policy_)) / (policy_.prefix + "_" + runStamp())).string();
if (!openFile(segmentPath(0))) return false;
// Prune AFTER opening, so the file we just created is counted and an
// aggressive keep_files cannot leave us with nothing.
prune();
return true;
}
bool FileLogSink::openFile(const std::string& path) {
fp_ = std::fopen(path.c_str(), "ab");
if (!fp_) {
fail("cannot open " + path + ": " + std::strerror(errno));
return false;
}
path_ = path;
bytes_ = 0;
lines_ = 0;
std::error_code ec;
const auto sz = fs::file_size(path, ec);
if (!ec) bytes_ = static_cast<long long>(sz);
if (!header_.empty()) {
const std::string h = header_ + "\n";
if (std::fwrite(h.data(), 1, h.size(), fp_) != h.size()) {
fail("write failed on " + path);
return false;
}
bytes_ += static_cast<long long>(h.size());
std::fflush(fp_);
}
return true;
}
void FileLogSink::write(LogLevel, LogCat, const std::string& line) {
if (failed_ || !fp_) return;
// Nothing here may escape: this runs inside an arbitrary LOG_* statement,
// under Logger's lock. A throw would propagate out of, say, a LOG_INFO in
// the control loop.
try {
const std::string out = today() + line + "\n";
// Rotate BEFORE the write that would cross the limit, so a file never
// exceeds max_bytes rather than overshooting by one line.
//
// `lines_` guards two degenerate cases: a max_bytes smaller than the
// header would otherwise rotate on every single line, burning through
// the whole retention set in a loop; and a single line longer than
// max_bytes would rotate into a fresh file and still not fit. Requiring
// at least one line in the current file makes both terminate - an
// oversized line simply lands whole in a file of its own.
if (policy_.max_bytes > 0 && lines_ > 0 &&
bytes_ + static_cast<long long>(out.size()) > policy_.max_bytes) {
rotate();
if (failed_ || !fp_) return;
}
if (std::fwrite(out.data(), 1, out.size(), fp_) != out.size()) {
fail("write failed on " + path_);
return;
}
bytes_ += static_cast<long long>(out.size());
++lines_;
// Flush, never fsync: a crashed process keeps these bytes, and fsync per
// line on eMMC would cost far more than the power-cut tail it would save.
std::fflush(fp_);
} catch (...) {
fail("exception while writing " + path_);
}
}
// "<base>.<NNN>.log". The segment is ZERO-PADDED and always present, including
// on the first file, so that a plain lexicographic sort of the directory is
// chronological. Without the padding ".log" sorts above ".2.log" ('l' > '2'),
// and pruning would keep the oldest segment and delete the newest.
std::string FileLogSink::segmentPath(int n) const {
char suffix[16];
std::snprintf(suffix, sizeof(suffix), ".%03d.log", n);
return base_ + suffix;
}
void FileLogSink::rotate() {
if (fp_) {
std::fclose(fp_);
fp_ = nullptr;
}
++rotation_;
if (!openFile(segmentPath(rotation_))) return;
prune();
}
void FileLogSink::prune() {
if (policy_.keep_files <= 0) return;
auto files = existingFiles(policy_); // newest first
if (static_cast<int>(files.size()) <= policy_.keep_files) return;
std::error_code ec;
for (size_t i = static_cast<size_t>(policy_.keep_files); i < files.size(); ++i) {
if (files[i] == path_) continue; // never delete the file we are writing
fs::remove(files[i], ec); // best effort; a failure here is not fatal
}
}
void FileLogSink::close() {
if (fp_) {
std::fflush(fp_);
std::fclose(fp_);
fp_ = nullptr;
}
path_.clear();
bytes_ = 0;
}
void FileLogSink::fail(const std::string& what) {
failed_ = true;
last_error_ = what;
if (fp_) {
std::fclose(fp_);
fp_ = nullptr;
}
}
} // namespace fgc

View File

@ -11,10 +11,12 @@ namespace fgc {
namespace { namespace {
std::atomic<LogLevel> g_level{LogLevel::Info}; std::atomic<LogLevel> g_level{LogLevel::Info}; // CONSOLE threshold
std::atomic<LogLevel> g_file_level{LogLevel::Off}; // Off => file wants nothing
std::atomic<unsigned> g_cats{0}; // every wire-trace category OFF by default std::atomic<unsigned> g_cats{0}; // every wire-trace category OFF by default
std::mutex g_mutex; std::mutex g_mutex;
Logger::LogSink g_sink; // empty => default stdout/stderr writer (below) Logger::LogSink g_sink; // empty => default stdout/stderr writer (below)
Logger::FileSink g_file_sink; // empty => no file logging
// Default writer: the stdout/stderr split this logger has always used. // Default writer: the stdout/stderr split this logger has always used.
void writeDefault(LogLevel level, const std::string& line) { void writeDefault(LogLevel level, const std::string& line) {
@ -83,17 +85,49 @@ void Logger::setSink(LogSink sink) {
void Logger::setLevel(LogLevel level) { g_level.store(level); } void Logger::setLevel(LogLevel level) { g_level.store(level); }
LogLevel Logger::level() { return g_level.load(); } LogLevel Logger::level() { return g_level.load(); }
bool Logger::enabled(LogLevel level) { return level >= g_level.load(); }
void Logger::setFileLevel(LogLevel level) { g_file_level.store(level); }
LogLevel Logger::fileLevel() { return g_file_level.load(); }
// The macros must let through anything EITHER destination wants, or a file set
// to debug could never receive a debug line while the console sits at info.
LogLevel Logger::effectiveLevel() {
const LogLevel c = g_level.load();
const LogLevel f = g_file_level.load();
return (f < c) ? f : c;
}
bool Logger::enabled(LogLevel level) { return level >= effectiveLevel(); }
void Logger::setFileSink(FileSink sink) {
std::lock_guard<std::mutex> lock(g_mutex);
g_file_sink = std::move(sink);
}
// Shared by both threshold setters; the config path needs the pure parse too.
static bool parseLevel(const std::string& s, LogLevel& out) {
std::string v = lower(s);
if (v == "trace") { out = LogLevel::Trace; return true; }
if (v == "debug") { out = LogLevel::Debug; return true; }
if (v == "info") { out = LogLevel::Info; return true; }
if (v == "warn" || v == "warning") { out = LogLevel::Warn; return true; }
if (v == "error") { out = LogLevel::Error; return true; }
if (v == "off" || v == "none") { out = LogLevel::Off; return true; }
return false;
}
bool Logger::setLevelFromString(const std::string& s) { bool Logger::setLevelFromString(const std::string& s) {
std::string v = lower(s); LogLevel l{};
if (v == "trace") { setLevel(LogLevel::Trace); return true; } if (!parseLevel(s, l)) return false;
if (v == "debug") { setLevel(LogLevel::Debug); return true; } setLevel(l);
if (v == "info") { setLevel(LogLevel::Info); return true; } return true;
if (v == "warn" || v == "warning") { setLevel(LogLevel::Warn); return true; } }
if (v == "error") { setLevel(LogLevel::Error); return true; }
if (v == "off" || v == "none") { setLevel(LogLevel::Off); return true; } bool Logger::setFileLevelFromString(const std::string& s) {
return false; LogLevel l{};
if (!parseLevel(s, l)) return false;
setFileLevel(l);
return true;
} }
void Logger::setCategories(unsigned mask) { g_cats.store(mask); } void Logger::setCategories(unsigned mask) { g_cats.store(mask); }
@ -141,16 +175,34 @@ LogStream::LogStream(LogLevel level) : level_(level), enabled_(Logger::enabled(l
LogStream::LogStream(LogLevel level, LogCat cat) LogStream::LogStream(LogLevel level, LogCat cat)
: level_(level), cat_(cat), : level_(level), cat_(cat),
enabled_(Logger::categoryEnabled(cat) && Logger::level() != LogLevel::Off) {} // A category line survives if EITHER destination would take it, which is
// why this asks the effective level rather than the console's.
enabled_(Logger::categoryEnabled(cat) && Logger::effectiveLevel() != LogLevel::Off) {}
void LogStream::commit() { void LogStream::commit() {
done_ = true; done_ = true;
if (!enabled_) return; if (!enabled_) return;
const char* label = (cat_ != LogCat::None) ? catTag(cat_) : tag(level_); const bool is_cat = (cat_ != LogCat::None);
const char* label = is_cat ? catTag(cat_) : tag(level_);
std::string line = timestamp() + " [" + label + "] " + buffer_.str(); std::string line = timestamp() + " [" + label + "] " + buffer_.str();
std::lock_guard<std::mutex> lock(g_mutex); std::lock_guard<std::mutex> lock(g_mutex);
// The file first: if the console path stalls or throws, the durable record
// is already out. Everything below runs with g_mutex HELD - a sink that
// logs from in here deadlocks the process.
//
// A category line bypasses BOTH level filters. It was already gated by
// categoryEnabled() at construction, and it carries level == Trace, so
// comparing it against a threshold would silently drop every wire trace at
// the default info level - i.e. break `--trace serial` for both outputs.
if (g_file_sink && (is_cat || level_ >= g_file_level.load())) {
g_file_sink(level_, cat_, line);
}
if (is_cat || level_ >= g_level.load()) {
if (g_sink) g_sink(level_, line); if (g_sink) g_sink(level_, line);
else writeDefault(level_, line); else writeDefault(level_, line);
} }
}
} // namespace fgc } // namespace fgc

View File

@ -25,6 +25,7 @@ add_executable(fgc_tests
test_tmccurrent.cpp test_tmccurrent.cpp
test_hardwarepresence.cpp test_hardwarepresence.cpp
test_hardwarechecks.cpp test_hardwarechecks.cpp
test_filelogsink.cpp
test_axisspeed.cpp test_axisspeed.cpp
test_firmwareconfig.cpp test_firmwareconfig.cpp
test_cameraprofile.cpp test_cameraprofile.cpp

215
tests/test_filelogsink.cpp Normal file
View File

@ -0,0 +1,215 @@
#include "doctest/doctest.h"
#include "fgc/FileLogSink.h"
#include <algorithm>
#include <filesystem>
#include <fstream>
#include <string>
#include <vector>
#include <unistd.h>
using namespace fgc;
namespace fs = std::filesystem;
namespace {
// A scratch directory per test case, removed on the way out even if a REQUIRE
// aborts the body.
struct TempDir {
fs::path path;
explicit TempDir(const char* tag) {
path = fs::temp_directory_path() /
("fgc-log-test-" + std::string(tag) + "-" + std::to_string(::getpid()));
fs::remove_all(path);
fs::create_directories(path);
}
~TempDir() {
std::error_code ec;
fs::remove_all(path, ec);
}
};
FileLogPolicy policyIn(const TempDir& d, long long max_bytes, int keep) {
FileLogPolicy p;
p.dir = d.path.string();
p.max_bytes = max_bytes;
p.keep_files = keep;
return p;
}
std::string read(const std::string& path) {
std::ifstream in(path, std::ios::binary);
return {std::istreambuf_iterator<char>(in), std::istreambuf_iterator<char>()};
}
// Every <prefix>_*.log in the directory, oldest first.
std::vector<std::string> filesOldestFirst(const TempDir& d) {
std::vector<std::string> out;
for (const auto& e : fs::directory_iterator(d.path))
if (e.path().extension() == ".log") out.push_back(e.path().filename().string());
std::sort(out.begin(), out.end());
return out;
}
} // namespace
TEST_CASE("a line lands in the file, dated, under a self-describing header") {
TempDir d("basic");
FileLogSink s;
REQUIRE(s.open(policyIn(d, 0, 0), "=== header ==="));
s.write(LogLevel::Info, LogCat::None, "12:00:00.000 [INFO ] hello");
s.close();
const std::string text = read((d.path / filesOldestFirst(d).front()).string());
CHECK(text.find("=== header ===") != std::string::npos);
CHECK(text.find("[INFO ] hello") != std::string::npos);
// Logger's own stamp carries no date, so the sink prepends one - otherwise a
// file spanning midnight is ambiguous. Check the shape, not just a dash.
const auto at = text.find("12:00:00.000");
REQUIRE(at != std::string::npos);
REQUIRE(at >= 11);
const std::string date = text.substr(at - 11, 11);
CHECK(date.size() == 11);
CHECK(date[4] == '-');
CHECK(date[7] == '-');
CHECK(date[10] == ' ');
}
TEST_CASE("rotation fires at the boundary, and never splits a line") {
TempDir d("rotate");
FileLogSink s;
// Header empty so the budget is entirely lines.
REQUIRE(s.open(policyIn(d, 200, 0), ""));
// Each written record is "YYYY-MM-DD " (11) + line + "\n".
const std::string line(50, 'x');
for (int i = 0; i < 10; ++i) s.write(LogLevel::Info, LogCat::None, line);
s.close();
const auto files = filesOldestFirst(d);
REQUIRE(files.size() > 1);
for (const auto& f : files) {
const std::string text = read((d.path / f).string());
CHECK(text.size() <= 200);
// A record is only ever whole: the file ends on a newline and contains
// no truncated 50-char run.
CHECK(text.back() == '\n');
}
}
TEST_CASE("segment names sort chronologically") {
// The bug this guards: with an unpadded suffix the FIRST segment is
// "<base>.log" and later ones "<base>.1.log". Lexicographically 'l' > '1',
// so the oldest file sorted as the newest and pruning deleted the wrong end.
TempDir d("sort");
FileLogSink s;
REQUIRE(s.open(policyIn(d, 120, 0), ""));
for (int i = 0; i < 6; ++i) s.write(LogLevel::Info, LogCat::None, std::string(40, 'a' + i));
s.close();
auto files = filesOldestFirst(d);
REQUIRE(files.size() >= 3);
// Written in order a.., b.., c..; sorted by name, the contents must follow.
const std::string first = read((d.path / files.front()).string());
const std::string second = read((d.path / files[1]).string());
CHECK(first.find(std::string(40, 'a')) != std::string::npos);
CHECK(second.find(std::string(40, 'a')) == std::string::npos);
// And the sink's own newest-first view must be the exact reverse.
auto newest = FileLogSink::existingFiles(policyIn(d, 120, 0));
REQUIRE(newest.size() == files.size());
CHECK(fs::path(newest.front()).filename().string() == files.back());
}
TEST_CASE("retention keeps the newest N and deletes the oldest") {
TempDir d("prune");
FileLogSink s;
REQUIRE(s.open(policyIn(d, 120, 3), ""));
for (int i = 0; i < 20; ++i) s.write(LogLevel::Info, LogCat::None, std::string(40, 'q'));
s.close();
auto files = filesOldestFirst(d);
CHECK(files.size() == 3);
// The survivors must be the LAST three segments, not the first three.
CHECK(files.back().find(".log") != std::string::npos);
auto newest = FileLogSink::existingFiles(policyIn(d, 120, 3));
CHECK(newest.size() == 3);
}
TEST_CASE("a max_bytes smaller than the header does not rotate forever") {
// Without the "at least one line in this file" guard, the header alone
// exceeds the cap, so every write rotates and the whole retention set is
// consumed in a loop - unbounded file churn from one misconfigured key.
TempDir d("tinycap");
FileLogSink s;
REQUIRE(s.open(policyIn(d, 10, 0), "=== a header much longer than ten bytes ==="));
for (int i = 0; i < 5; ++i) s.write(LogLevel::Info, LogCat::None, "some line");
s.close();
// Five writes, each in its own file because the cap is tiny - but exactly
// five, not hundreds.
CHECK(filesOldestFirst(d).size() <= 6);
}
TEST_CASE("a single line longer than max_bytes still lands, whole, and terminates") {
TempDir d("oversize");
FileLogSink s;
REQUIRE(s.open(policyIn(d, 50, 0), ""));
const std::string huge(500, 'z');
s.write(LogLevel::Info, LogCat::None, "first");
s.write(LogLevel::Info, LogCat::None, huge);
s.close();
bool found = false;
for (const auto& f : filesOldestFirst(d))
if (read((d.path / f).string()).find(huge) != std::string::npos) found = true;
CHECK(found);
}
TEST_CASE("the header is re-emitted after each rotation") {
TempDir d("hdr");
FileLogSink s;
REQUIRE(s.open(policyIn(d, 160, 0), "=== HDR ==="));
for (int i = 0; i < 8; ++i) s.write(LogLevel::Info, LogCat::None, std::string(40, 'h'));
s.close();
const auto files = filesOldestFirst(d);
REQUIRE(files.size() > 1);
for (const auto& f : files)
CHECK(read((d.path / f).string()).rfind("=== HDR ===", 0) == 0);
}
TEST_CASE("an unopenable path fails cleanly and writes become no-ops") {
// The sink runs inside Logger's lock and must never throw or log; a failure
// has to be latched and reported by polling instead.
TempDir d("fail");
const fs::path blocker = d.path / "blocked";
{ std::ofstream(blocker) << "not a directory"; }
FileLogPolicy p = policyIn(d, 0, 0);
p.dir = (blocker / "sub").string(); // parent is a regular file
FileLogSink s;
CHECK_FALSE(s.open(p, "hdr"));
CHECK(s.failed());
CHECK_FALSE(s.lastError().empty());
CHECK_NOTHROW(s.write(LogLevel::Error, LogCat::None, "after failure"));
CHECK_FALSE(s.isOpen());
}
TEST_CASE("the prefix cannot be confused with the self-test reports") {
// Application::latestPriorTestReport() scans this same directory for
// test_*.log and takes the lexicographically greatest. Our files must not
// appear in that scan.
TempDir d("prefix");
FileLogSink s;
REQUIRE(s.open(policyIn(d, 0, 0), ""));
s.write(LogLevel::Info, LogCat::None, "x");
s.close();
for (const auto& f : filesOldestFirst(d)) {
CHECK(f.rfind("fgc_", 0) == 0);
CHECK(f.rfind("test_", 0) != 0);
}
}

View File

@ -5,6 +5,7 @@
#include <iostream> #include <iostream>
#include <sstream> #include <sstream>
#include <string> #include <string>
#include <vector>
using namespace fgc; using namespace fgc;
@ -114,3 +115,132 @@ TEST_CASE("LOG_TRACE_CAT gating is independent of the linear level") {
Logger::setCategories(0); Logger::setCategories(0);
Logger::setLevel(LogLevel::Info); Logger::setLevel(LogLevel::Info);
} }
// --- the file sink: a second, independent destination ----------------------
namespace {
// Logger state is process-global and doctest runs every case in one process, so
// a case that leaks a file sink makes LATER cases write into a deleted temp dir.
// Restoring at the end of the body is not enough: a failed REQUIRE skips it.
struct LoggerStateGuard {
fgc::LogLevel console = fgc::Logger::level();
fgc::LogLevel file = fgc::Logger::fileLevel();
unsigned cats = fgc::Logger::categories();
~LoggerStateGuard() {
fgc::Logger::setFileSink({});
fgc::Logger::setLevel(console);
fgc::Logger::setFileLevel(file);
fgc::Logger::setCategories(cats);
}
};
// Collects what the file sink is handed.
struct Captured {
std::vector<std::string> lines;
std::vector<fgc::LogCat> cats;
bool has(const std::string& needle) const {
for (const auto& l : lines)
if (l.find(needle) != std::string::npos) return true;
return false;
}
};
} // namespace
TEST_CASE("the file is more verbose than the console, independently") {
LoggerStateGuard guard;
Captured cap;
Logger::setFileSink([&](LogLevel, LogCat c, const std::string& l) {
cap.lines.push_back(l);
cap.cats.push_back(c);
});
Logger::setLevel(LogLevel::Info); // console
Logger::setFileLevel(LogLevel::Debug); // file
// The macros must gate on the MORE verbose of the two, or the debug line
// would never be built at all.
CHECK(Logger::effectiveLevel() == LogLevel::Debug);
CHECK(Logger::enabled(LogLevel::Debug));
const std::string out = captureCout([] {
LOG_DEBUG << "detail-for-file";
LOG_INFO << "for-both";
});
CHECK(cap.has("detail-for-file")); // file got it
CHECK(out.find("detail-for-file") == std::string::npos); // console did not
CHECK(cap.has("for-both"));
CHECK(out.find("for-both") != std::string::npos);
}
TEST_CASE("a wire trace reaches the file even though its level is below the threshold") {
// The regression this design is most likely to introduce. A category line
// carries level == Trace; filtering it against file_level (debug) would drop
// every wire trace silently, and `--trace serial` would write nothing.
LoggerStateGuard guard;
Captured cap;
Logger::setFileSink([&](LogLevel, LogCat c, const std::string& l) {
cap.lines.push_back(l);
cap.cats.push_back(c);
});
Logger::setLevel(LogLevel::Info);
Logger::setFileLevel(LogLevel::Debug);
SUBCASE("category off: nowhere") {
Logger::setCategories(0);
const std::string out = captureCout([] { LOG_TRACE_CAT(LogCat::Serial) << "TX ping"; });
CHECK_FALSE(cap.has("TX ping"));
CHECK(out.find("TX ping") == std::string::npos);
}
SUBCASE("category on: both, and the file is told which category") {
Logger::setCategories(static_cast<unsigned>(LogCat::Serial));
const std::string out = captureCout([] { LOG_TRACE_CAT(LogCat::Serial) << "TX ping"; });
CHECK(cap.has("TX ping"));
CHECK(cap.has("[SERIAL]"));
CHECK(out.find("TX ping") != std::string::npos);
REQUIRE_FALSE(cap.cats.empty());
CHECK(cap.cats.front() == LogCat::Serial);
}
}
TEST_CASE("the console can be silenced without silencing the file") {
// `--log-level off` now means the CONSOLE is off. A tower quietened on
// screen must still be writing its record.
LoggerStateGuard guard;
Captured cap;
Logger::setFileSink([&](LogLevel, LogCat, const std::string& l) { cap.lines.push_back(l); });
Logger::setLevel(LogLevel::Off);
Logger::setFileLevel(LogLevel::Info);
const std::string out = captureCout([] { LOG_ERROR << "still-recorded"; });
CHECK(cap.has("still-recorded"));
CHECK(out.find("still-recorded") == std::string::npos);
}
TEST_CASE("with no file sink the logger behaves exactly as before") {
LoggerStateGuard guard;
Logger::setFileSink({});
Logger::setFileLevel(LogLevel::Off);
Logger::setLevel(LogLevel::Info);
// Off is the identity for the min(), so the gate is bit-identical to the
// pre-change behaviour.
CHECK(Logger::effectiveLevel() == LogLevel::Info);
CHECK_FALSE(Logger::enabled(LogLevel::Debug));
CHECK(Logger::enabled(LogLevel::Info));
const std::string out = captureCout([] { LOG_INFO << "unchanged"; });
CHECK(out.find("unchanged") != std::string::npos);
}
TEST_CASE("setFileLevelFromString accepts the same words as the console one") {
LoggerStateGuard guard;
CHECK(Logger::setFileLevelFromString("debug"));
CHECK(Logger::fileLevel() == LogLevel::Debug);
CHECK(Logger::setFileLevelFromString("WARNING"));
CHECK(Logger::fileLevel() == LogLevel::Warn);
CHECK(Logger::setFileLevelFromString("off"));
CHECK(Logger::fileLevel() == LogLevel::Off);
// A bad word leaves it untouched rather than guessing.
CHECK_FALSE(Logger::setFileLevelFromString("loud"));
CHECK(Logger::fileLevel() == LogLevel::Off);
}