diff --git a/CMakeLists.txt b/CMakeLists.txt index c808742..0359561 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -66,6 +66,7 @@ add_library(fgc_core STATIC src/core/TmcCurrent.cpp src/core/HardwarePresence.cpp src/core/HardwareChecks.cpp + src/core/FileLogSink.cpp src/core/AxisSpeed.cpp src/core/FirmwareConfig.cpp src/core/ScanGrid.cpp diff --git a/config/config.example.ini b/config/config.example.ini index 1ae9627..8693f0a 100644 --- a/config/config.example.ini +++ b/config/config.example.ini @@ -310,9 +310,32 @@ enable_tui = false [Logging] ; 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 ; Verbatim per-category wire tracing, independent of the level above. Comma list ; 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. ; [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 = + +; --- 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: /logs/fgc_..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 = diff --git a/docs/configuration.md b/docs/configuration.md index 70fa3cd..76e8ddc 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -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_addr` | int | `68` (`0x44`) | SHT41 I2C slave address; decimal or `0x`-prefixed hex | | `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` | `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`) | | `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 | @@ -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 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_..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 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) | | `--tui` | Show the full-screen terminal dashboard (overrides `[UI] enable_tui`) | | `--no-tui` | Force the headless line console (overrides config; wins over `--tui`) | -| `--log-level ` | `trace`/`debug`/`info`/`warn`/`error`/`off` | +| `--log-level ` | **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 ` | File level, independent of `--log-level` (default `debug`) | | `--trace ` | 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`. diff --git a/docs/modules-reference.md b/docs/modules-reference.md index ad9e25b..8b0b003 100644 --- a/docs/modules-reference.md +++ b/docs/modules-reference.md @@ -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/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/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/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` | diff --git a/include/fgc/Config.h b/include/fgc/Config.h index 861a095..2b1ce30 100644 --- a/include/fgc/Config.h +++ b/include/fgc/Config.h @@ -273,6 +273,19 @@ struct EnvConfig { struct LoggingConfig { 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 + + // 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 { diff --git a/include/fgc/FileLogSink.h b/include/fgc/FileLogSink.h new file mode 100644 index 0000000..09950f1 --- /dev/null +++ b/include/fgc/FileLogSink.h @@ -0,0 +1,98 @@ +#pragma once + +#include "fgc/Logger.h" + +#include +#include +#include + +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 _*.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 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 "..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 diff --git a/include/fgc/Logger.h b/include/fgc/Logger.h index b563092..44ce2b0 100644 --- a/include/fgc/Logger.h +++ b/include/fgc/Logger.h @@ -30,6 +30,9 @@ enum class LogCat : unsigned { // Lines at Warn/Error go to stderr; everything else to stdout. class Logger { 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 LogLevel level(); static bool enabled(LogLevel level); @@ -62,6 +65,37 @@ public: // function to restore the default writer. Thread-safe. using LogSink = std::function; 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; + 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(). diff --git a/main.cpp b/main.cpp index 6e1d043..b1c1dfb 100644 --- a/main.cpp +++ b/main.cpp @@ -1,16 +1,45 @@ #include "fgc/Application.h" #include "fgc/Config.h" +#include "fgc/FileLogSink.h" #include "fgc/Logger.h" #include "fgc/Paths.h" #include "fgc/SingleInstance.h" #include +#include + +#include #include namespace po = boost::program_options; 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[]) { po::options_description desc("Fire Gimbal Control options"); desc.add_options() @@ -35,7 +64,12 @@ int main(int argc, char* argv[]) { ("no-lock", po::bool_switch(), "skip the single-instance lock (dev only: for a second mock-only instance)") ("lock-file", po::value(), "path to the single-instance lockfile") - ("log-level", po::value(), "trace|debug|info|warn|error|off") + ("log-level", po::value(), + "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(), + "log-file verbosity, independent of --log-level (default debug)") ("trace", po::value(), "verbatim wire trace, comma list: serial,mqtt,camera,control,all,none"); @@ -73,6 +107,12 @@ int main(int argc, char* argv[]) { 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(); + const bool opts_no_log_file = vm["no-log-file"].as(); + AppConfig cfg; try { 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"; 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(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; // Only one instance may run: a second would fight the first over the motor's diff --git a/src/core/Config.cpp b/src/core/Config.cpp index c5c4795..ecf3d06 100644 --- a/src/core/Config.cpp +++ b/src/core/Config.cpp @@ -431,6 +431,18 @@ AppConfig ConfigLoader::fromMap(const std::map& kv) { cfg.logging.level = get(kv, "Logging.level", cfg.logging.level); 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); diff --git a/src/core/FileLogSink.cpp b/src/core/FileLogSink.cpp new file mode 100644 index 0000000..de9824a --- /dev/null +++ b/src/core/FileLogSink.cpp @@ -0,0 +1,214 @@ +#include "fgc/FileLogSink.h" + +#include "fgc/Paths.h" + +#include +#include +#include +#include +#include +#include + +// 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 FileLogSink::existingFiles(const FileLogPolicy& policy) { + std::vector 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()); + 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; + } + + // "/_"; 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(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(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(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(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_); + } +} + +// "..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(files.size()) <= policy_.keep_files) return; + + std::error_code ec; + for (size_t i = static_cast(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 diff --git a/src/core/Logger.cpp b/src/core/Logger.cpp index 937a1da..ca246f0 100644 --- a/src/core/Logger.cpp +++ b/src/core/Logger.cpp @@ -11,10 +11,12 @@ namespace fgc { namespace { -std::atomic g_level{LogLevel::Info}; +std::atomic g_level{LogLevel::Info}; // CONSOLE threshold +std::atomic g_file_level{LogLevel::Off}; // Off => file wants nothing std::atomic g_cats{0}; // every wire-trace category OFF by default std::mutex g_mutex; 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. 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); } 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 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) { - std::string v = lower(s); - if (v == "trace") { setLevel(LogLevel::Trace); return true; } - if (v == "debug") { setLevel(LogLevel::Debug); return true; } - if (v == "info") { setLevel(LogLevel::Info); 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; } - return false; + LogLevel l{}; + if (!parseLevel(s, l)) return false; + setLevel(l); + return true; +} + +bool Logger::setFileLevelFromString(const std::string& s) { + LogLevel l{}; + if (!parseLevel(s, l)) return false; + setFileLevel(l); + return true; } 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) : 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() { done_ = true; if (!enabled_) return; - const char* label = (cat_ != LogCat::None) ? catTag(cat_) : tag(level_); - std::string line = timestamp() + " [" + label + "] " + buffer_.str(); + const bool is_cat = (cat_ != LogCat::None); + const char* label = is_cat ? catTag(cat_) : tag(level_); + std::string line = timestamp() + " [" + label + "] " + buffer_.str(); + std::lock_guard lock(g_mutex); - if (g_sink) g_sink(level_, line); - else writeDefault(level_, line); + + // 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); + else writeDefault(level_, line); + } } } // namespace fgc diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 149f523..e11fa24 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -25,6 +25,7 @@ add_executable(fgc_tests test_tmccurrent.cpp test_hardwarepresence.cpp test_hardwarechecks.cpp + test_filelogsink.cpp test_axisspeed.cpp test_firmwareconfig.cpp test_cameraprofile.cpp diff --git a/tests/test_filelogsink.cpp b/tests/test_filelogsink.cpp new file mode 100644 index 0000000..94bdf25 --- /dev/null +++ b/tests/test_filelogsink.cpp @@ -0,0 +1,215 @@ +#include "doctest/doctest.h" +#include "fgc/FileLogSink.h" + +#include +#include +#include +#include +#include + +#include + +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(in), std::istreambuf_iterator()}; +} + +// Every _*.log in the directory, oldest first. +std::vector filesOldestFirst(const TempDir& d) { + std::vector 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 + // ".log" and later ones ".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); + } +} diff --git a/tests/test_logger.cpp b/tests/test_logger.cpp index df779d2..cc7af27 100644 --- a/tests/test_logger.cpp +++ b/tests/test_logger.cpp @@ -5,6 +5,7 @@ #include #include #include +#include using namespace fgc; @@ -114,3 +115,132 @@ TEST_CASE("LOG_TRACE_CAT gating is independent of the linear level") { Logger::setCategories(0); 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 lines; + std::vector 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(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); +}