From 753fc681d36eee75d5a877efb36e3bc43b2af16b Mon Sep 17 00:00:00 2001 From: Myoungho Shin Date: Wed, 29 Jul 2026 07:28:30 -0700 Subject: [PATCH 1/5] feat(logger): add crash-safe deadline window rotation Publish low-volume log windows from the collector beat without blocking it on compression. Retired windows are exported asynchronously with monotonic per-channel sequence numbers, bounded backlog telemetry, and deterministic shutdown draining. Make the spool transaction crash-safe through .part promotion, validated gzip recovery, atomic no-replace moves, payload-aware collision handling, and durable transport-loss markers. Upload and launcher completion now refuse sessions with known loss while isolating unrelated old sessions. Add mutation-checked rotation, salvage, collision, deadline, failure, pruning, and upload recovery coverage. --- daemon/launcher/trace_command_common.cpp | 60 +- include/gpufl/core/env_vars.hpp | 7 + include/gpufl/core/gpufl.cpp | 5 + include/gpufl/core/logger/file_compressor.cpp | 48 +- include/gpufl/core/logger/file_compressor.hpp | 10 + include/gpufl/core/logger/file_log_sink.cpp | 284 +++++- include/gpufl/core/logger/file_log_sink.hpp | 130 ++- include/gpufl/core/logger/log_rotator.cpp | 214 +++-- include/gpufl/core/logger/log_rotator.hpp | 100 ++- include/gpufl/core/logger/log_salvage.cpp | 584 +++++++++++- include/gpufl/core/logger/log_salvage.hpp | 72 +- include/gpufl/core/logger/log_sink.hpp | 9 + include/gpufl/core/logger/logger.cpp | 7 + include/gpufl/core/logger/logger.hpp | 39 + include/gpufl/core/monitor.cpp | 6 + include/gpufl/upload/upload_logs.cpp | 102 ++- tests/CMakeLists.txt | 1 + tests/core/test_file_log_sink_rotation.cpp | 839 ++++++++++++++++++ tests/upload/test_upload_logs.cpp | 88 ++ 19 files changed, 2394 insertions(+), 211 deletions(-) create mode 100644 tests/core/test_file_log_sink_rotation.cpp diff --git a/daemon/launcher/trace_command_common.cpp b/daemon/launcher/trace_command_common.cpp index 8f05dff..5d21ec8 100644 --- a/daemon/launcher/trace_command_common.cpp +++ b/daemon/launcher/trace_command_common.cpp @@ -288,37 +288,21 @@ bool appendLineToGzipLog(const fs::path& gz_path, const std::string& line) { return true; } -// Highest existing system..log[.gz] window index under session_dir (0 if none). -int highestSystemWindowIndex(const fs::path& session_dir) { - int max_idx = 0; - std::error_code ec; - for (const auto& entry : fs::directory_iterator(session_dir, ec)) { - if (ec) break; - if (!entry.is_regular_file(ec)) continue; - std::string name = entry.path().filename().string(); - if (name.size() > 3 && name.compare(name.size() - 3, 3, ".gz") == 0) { - name.resize(name.size() - 3); - } - if (name.size() <= 4 || name.compare(name.size() - 4, 4, ".log") != 0) continue; - name.resize(name.size() - 4); // "system" or "system." - if (name.rfind("system.", 0) != 0) continue; // skip the non-indexed "system" - const std::string suffix = name.substr(std::string("system.").size()); - if (suffix.empty() || - !std::all_of(suffix.begin(), suffix.end(), - [](unsigned char c) { return std::isdigit(c); })) { - continue; - } - try { max_idx = std::max(max_idx, std::stoi(suffix)); } catch (...) {} - } - return max_idx; -} - bool appendSyntheticShutdown(const fs::path& session_dir, const std::string& session_id, const SessionLifecycleInfo& info, const SyntheticShutdownContext& context) { const std::string line = syntheticShutdownLine(session_id, info, context); - const std::string base = "system." + std::to_string(highestSystemWindowIndex(session_dir) + 1) + ".log"; + // Allocate through the shared allocator, which also counts windows still + // sitting in `.tmp`. highestSystemWindowIndex() only scans the session + // ROOT, so a deferred window in `.tmp` did not reserve its index and the + // marker could be written onto it - one of the two then gets deleted as + // a "duplicate", losing either a full window or the shutdown record the + // backend needs to finalize the session. + const std::string base = + "system." + + std::to_string(gpufl::nextLogWindowIndex(session_dir, "system")) + + ".log"; const fs::path window_gz = session_dir / (base + ".gz"); std::error_code ec; if (fs::exists(window_gz, ec)) { @@ -425,6 +409,17 @@ void signalSessionsComplete(const fs::path& output_dir, if (!isSessionDirectory(entry)) continue; const std::string session_id = entry.path().filename().string(); + const auto lost_windows = transportLossMarkerCount(entry.path()); + if (lost_windows > 0) { + if (!quiet) { + std::fprintf( + stderr, + "gpufl trace --upload: NOT signalling session-complete " + "for %s: %zu transport window(s) are known lost\n", + session_id.c_str(), lost_windows); + } + continue; + } futures.push_back(std::async(std::launch::async, [config, session_id]() { return std::make_pair(session_id, postSessionComplete(config, session_id)); })); @@ -486,6 +481,19 @@ int repairUncompressedLogs(const fs::path& root) { const fs::path gz_path(path.string() + ".gz"); std::error_code exists_ec; + // EXISTS is not VALID. A compress that died midway - or a rename that + // hit the disk before its data - leaves a truncated or empty `.gz`, + // and deleting the raw because that file is merely present destroys + // the only complete copy of the window. Re-compress from the raw + // instead when the `.gz` does not decode. + if (fs::exists(gz_path, exists_ec) && !isValidGzipFile(gz_path)) { + std::fprintf(stderr, + "[gpufl] warning: %s is not a readable gzip - " + "rebuilding it from %s\n", + gz_path.string().c_str(), path.string().c_str()); + std::error_code rm_ec; + fs::remove(gz_path, rm_ec); + } if (fs::exists(gz_path, exists_ec)) { std::error_code remove_ec; if (!removeWithRetry(path, remove_ec)) { diff --git a/include/gpufl/core/env_vars.hpp b/include/gpufl/core/env_vars.hpp index 3a22db3..b1c1380 100644 --- a/include/gpufl/core/env_vars.hpp +++ b/include/gpufl/core/env_vars.hpp @@ -82,6 +82,13 @@ constexpr const char* kDebugOutput = "GPUFL_DEBUG"; // exercises rotation without writing tens of MB. constexpr const char* kLogRotateBytes = "GPUFL_LOG_ROTATE_BYTES"; +// Opt-in (>0): also rotate a channel window once the data in it spans this +// many milliseconds (monotonic clock, measured from the window's first +// write). Publishes transport windows on a time cadence so low-volume +// channels stop sitting in `.tmp` until 64 MiB accumulates - the agent +// ships each finished window mid-run. An empty window is never rotated. +constexpr const char* kLogRotateAfterMs = "GPUFL_LOG_ROTATE_AFTER_MS"; + // Opt-in ("1", "true", "yes", "on"): flush each log line immediately. // Useful when diagnosing whether missing records are buffered in userspace. constexpr const char* kFlushLogsAlways = "GPUFL_FLUSH_LOGS_ALWAYS"; diff --git a/include/gpufl/core/gpufl.cpp b/include/gpufl/core/gpufl.cpp index 6b60252..393e25c 100644 --- a/include/gpufl/core/gpufl.cpp +++ b/include/gpufl/core/gpufl.cpp @@ -331,6 +331,11 @@ bool init(const InitOptions& opts) { logOpts.rotate_bytes = static_cast(bytes); } } + if (const char* v = std::getenv(env::kLogRotateAfterMs)) { + if (const auto ms = std::strtoll(v, nullptr, 10); ms > 0) { + logOpts.rotate_after_ms = static_cast(ms); + } + } g_lastLogPath = logPath; g_lastSessionId = rt->session_id; diff --git a/include/gpufl/core/logger/file_compressor.cpp b/include/gpufl/core/logger/file_compressor.cpp index 6baef25..15dc010 100644 --- a/include/gpufl/core/logger/file_compressor.cpp +++ b/include/gpufl/core/logger/file_compressor.cpp @@ -28,6 +28,24 @@ bool removeWithRetry(const fs::path& p, std::error_code& ec) { } } // namespace +bool removeOrTruncateFile(const std::string& path) { + if (path.empty()) return true; + + const fs::path p(path); + std::error_code ec; + if (removeWithRetry(p, ec)) return true; + + // Windows can deny delete sharing while still allowing the owner to + // truncate. An empty husk is harmless and the temp-dir cleanup removes it + // once the holder lets go. + std::ofstream trunc(p, std::ios::out | std::ios::trunc); + if (!trunc) return false; + trunc.close(); + + std::error_code size_ec; + return fs::file_size(p, size_ec) == 0 && !size_ec; +} + bool GzipFileCompressor::compressTo(const std::string& src, const std::string& dst) { if (src.empty() || dst.empty()) return false; @@ -71,25 +89,17 @@ bool GzipFileCompressor::compress(const std::string& path) { const bool ok = compressTo(path, outPath); if (!ok) return false; - std::error_code ec; - if (!removeWithRetry(path, ec)) { - // A holder outlived the retries (a tail, an editor, an AV scan). - // Windows lets nobody delete a file held without delete sharing - - // but write sharing is common, so TRUNCATE the original instead: - // the data then exists exactly once (in the .gz) and the leftover - // is an empty husk that any later cleanup removes once the holder - // lets go. - std::ofstream trunc(path, std::ios::out | std::ios::trunc); - if (trunc) { - GFL_LOG_DEBUG("[Logger] compressed '", path, - "' - original was held, truncated to empty " - "instead of removed."); - } else { - GFL_LOG_ERROR("[Logger] compressed '", path, - "' but could not remove or truncate the original " - "(", ec.message(), - ") - stale .log left next to the .gz."); - } + if (!removeOrTruncateFile(path)) { + // Keep the source authoritative when the exact-once transition could + // not complete. A caller seeing false may retry safely; leaving both + // a non-empty raw file and a successful gzip would invite duplicate + // salvage/upload. + std::error_code rm_ec; + fs::remove(outPath, rm_ec); + GFL_LOG_ERROR("[Logger] compressed '", path, + "' but could not remove or truncate the original; " + "discarded the gzip and kept the raw source."); + return false; } return true; } diff --git a/include/gpufl/core/logger/file_compressor.hpp b/include/gpufl/core/logger/file_compressor.hpp index baf2d1c..3d3149e 100644 --- a/include/gpufl/core/logger/file_compressor.hpp +++ b/include/gpufl/core/logger/file_compressor.hpp @@ -4,6 +4,16 @@ namespace gpufl { +/** + * Remove a file with the short Windows sharing-violation retry used by the + * logger, falling back to truncation when a holder prevents unlinking. + * + * Returns true only when the path is gone or is an empty husk. Callers use + * this to preserve the single-authority spool contract: a completed gzip + * must never be published while an identical non-empty raw window remains. + */ +bool removeOrTruncateFile(const std::string& path); + class IFileCompressor { public: virtual ~IFileCompressor() = default; diff --git a/include/gpufl/core/logger/file_log_sink.cpp b/include/gpufl/core/logger/file_log_sink.cpp index 199b854..1654892 100644 --- a/include/gpufl/core/logger/file_log_sink.cpp +++ b/include/gpufl/core/logger/file_log_sink.cpp @@ -1,5 +1,7 @@ #include "gpufl/core/logger/file_log_sink.hpp" +#include +#include #include #include "gpufl/core/debug_logger.hpp" @@ -12,8 +14,9 @@ namespace fs = std::filesystem; // --- FileChannel --- (behavior preserved from pre-refactor Logger::LogChannel) -FileLogSink::FileChannel::FileChannel(std::string name, Logger::Options opt) - : name_(std::move(name)), opt_(std::move(opt)) { +FileLogSink::FileChannel::FileChannel(std::string name, Logger::Options opt, + FileLogSink* owner) + : name_(std::move(name)), opt_(std::move(opt)), owner_(owner) { if (opt_.compress_rotated) { compressor_ = std::make_unique(); } @@ -73,7 +76,10 @@ void FileLogSink::FileChannel::closeLocked() { // gzips the orphan .log on first read instead. That keeps the // on-wire format uniform regardless of whether shutdown ran. if (rotator_) { - rotator_->compressActive(); + if (next_window_index_ == 0) { + next_window_index_ = rotator_->nextWindowIndex(); + } + (void)rotator_->compressActive(next_window_index_); } opened_ = false; } @@ -124,17 +130,117 @@ void FileLogSink::FileChannel::ensureOpenLocked() { } } -void FileLogSink::FileChannel::rotateLocked() { +std::int64_t FileLogSink::FileChannel::nowMs() const { + if (opt_.now_ms) return opt_.now_ms(); + return std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()) + .count(); +} + +void FileLogSink::FileChannel::rotateLocked(RotateTrigger trigger) { if (!opened_) return; if (stream_.is_open()) { stream_.flush(); stream_.close(); } - rotator_->rotate(); - current_bytes_ = 0; + // CUTOVER ONLY - a rename, no compression, no retry sleeps. Whoever + // hit the boundary (the collector beat, or a writer that crossed + // rotate_bytes) must not wait on gzip: the collector would stop + // draining the CUPTI ring, and a writer would hold this channel's + // lock against every other event producer. + // Allocate from this channel's own counter. Seeded once, lazily, so the + // seed reflects anything a salvage pass published before the first + // rotation; after that the filesystem never decides an index again (see + // next_window_index_ for why re-deriving it races the export worker). + if (next_window_index_ == 0) { + next_window_index_ = rotator_->nextWindowIndex(); + } + const std::size_t index = next_window_index_; + const auto result = rotator_->retireActiveWindow(index); + const char* trigger_name = + trigger == RotateTrigger::Size ? "size" : "time"; + switch (result) { + case LogFileRotator::RetireResult::Retired: { + // Consumed only on success: a Blocked cutover leaves the data in + // the active window, so the same index must be retried. + ++next_window_index_; + const std::uint64_t retired_bytes = + static_cast(current_bytes_); + if (trigger == RotateTrigger::Size) { + ++rotation_stats_.by_size; + } else { + ++rotation_stats_.by_time; + } + window_first_write_ms_ = -1; + GFL_LOG_DEBUG("[Logger] cut over '", name_, "' window ", index, + ": trigger=", trigger_name, + " bytes=", current_bytes_); + ensureOpenLocked(); // fresh, empty active window + // Enqueue AFTER reopening so the channel is immediately + // writable again even if the worker starts exporting at once. + if (owner_) owner_->enqueueRetired(this, index, retired_bytes); + return; + } + case LogFileRotator::RetireResult::Blocked: + // The data is still the active window. Keep its first-write + // age so the very next beat retries instead of waiting out a + // fresh rotate_after_ms. + ++rotation_stats_.cutover_blocked; + break; + case LogFileRotator::RetireResult::NoData: + break; + } ensureOpenLocked(); } +void FileLogSink::FileChannel::exportRetired(const std::size_t index) { + if (opt_.before_retired_export) opt_.before_retired_export(); + const auto started = std::chrono::steady_clock::now(); + std::size_t pruned = 0; + // No channel lock held: the retired file is immutable and nothing + // writes to it any more, so gzip and the publish backoff cost this + // worker thread only. + const auto result = rotator_->exportRetiredWindow(index, &pruned); + const auto elapsed_ms = + std::chrono::duration_cast( + std::chrono::steady_clock::now() - started) + .count(); + + std::lock_guard lk(mu_); + rotation_stats_.pruned_windows += pruned; + if (elapsed_ms > rotation_stats_.max_export_ms) { + rotation_stats_.max_export_ms = elapsed_ms; + } + switch (result) { + case LogFileRotator::ExportWindowResult::Published: + ++rotation_stats_.published; + break; + case LogFileRotator::ExportWindowResult::StagedForSalvage: + // Compressed but not published: the salvage pass finishes it. + ++rotation_stats_.staged; + break; + case LogFileRotator::ExportWindowResult::DeferredInActive: + // Compression failed; the retired file stays in `.tmp` and the + // salvage pass compresses it at close. + ++rotation_stats_.export_failed; + break; + case LogFileRotator::ExportWindowResult::NoData: + break; + } +} + +bool FileLogSink::FileChannel::timeDueLocked(const std::int64_t now) const { + return opt_.rotate_after_ms > 0 && window_first_write_ms_ >= 0 && + (now - window_first_write_ms_) >= opt_.rotate_after_ms; +} + +void FileLogSink::FileChannel::rotateIfDue() { + std::lock_guard lk(mu_); + if (!opened_) return; + if (!timeDueLocked(nowMs())) return; + rotateLocked(RotateTrigger::Time); +} + void FileLogSink::FileChannel::write(std::string_view line) { std::lock_guard lk(mu_); if (!opened_) { @@ -147,9 +253,23 @@ void FileLogSink::FileChannel::write(std::string_view line) { return; } const size_t bytesToWrite = line.size() + 1; - if (opt_.rotate_bytes > 0 && - (current_bytes_ + bytesToWrite) > opt_.rotate_bytes) { - rotateLocked(); + // Two rotation triggers, whichever is due first. Time is evaluated + // before size: an overdue window was already due BEFORE this write's + // bytes existed, so it is the honest "which came first" answer when + // both hold at once. The time trigger only ever fires on a NON-empty + // window (window_first_write_ms_ >= 0), so idle channels never + // publish empty window files, and the monotonic clock (nowMs) means + // wall-time jumps can neither fire nor starve it. This write-path + // check gives immediacy on busy channels; quiet channels are covered + // by the collector beat calling rotateIfDue(). + const std::int64_t now = + opt_.rotate_after_ms > 0 ? nowMs() : 0; + const bool time_due = timeDueLocked(now); + const bool size_due = + opt_.rotate_bytes > 0 && + (current_bytes_ + bytesToWrite) > opt_.rotate_bytes; + if (time_due || size_due) { + rotateLocked(time_due ? RotateTrigger::Time : RotateTrigger::Size); if (!stream_.good()) { GFL_LOG_ERROR("Write failed after rotate for '", name_, "'"); return; @@ -179,17 +299,25 @@ void FileLogSink::FileChannel::write(std::string_view line) { if (opt_.flush_always) { stream_.flush(); } + if (opt_.rotate_after_ms > 0 && window_first_write_ms_ < 0) { + window_first_write_ms_ = now; + } current_bytes_ += bytesToWrite; } +FileLogSink::RotationStats FileLogSink::FileChannel::rotationStats() const { + std::lock_guard lk(mu_); + return rotation_stats_; +} + // --- FileLogSink --- FileLogSink::FileLogSink(const Logger::Options& opt) { if (opt.base_path.empty()) return; - chanDevice_ = std::make_unique("device", opt); - chanScope_ = std::make_unique("scope", opt); - chanSystem_ = std::make_unique("system", opt); - chanSass_ = std::make_unique("sass", opt); + chanDevice_ = std::make_unique("device", opt, this); + chanScope_ = std::make_unique("scope", opt, this); + chanSystem_ = std::make_unique("system", opt, this); + chanSass_ = std::make_unique("sass", opt, this); LogRotationOptions r{}; r.base_path = opt.base_path; r.session_id = opt.session_id; @@ -205,7 +333,124 @@ bool FileLogSink::anyChannelOpen() const { (chanSass_ && chanSass_->isOpen()); } +FileLogSink::RotationStats FileLogSink::rotationStats() const { + RotationStats total; + for (const FileChannel* ch : + {chanDevice_.get(), chanScope_.get(), chanSystem_.get(), + chanSass_.get()}) { + if (!ch) continue; + const RotationStats s = ch->rotationStats(); + total.by_size += s.by_size; + total.by_time += s.by_time; + total.cutover_blocked += s.cutover_blocked; + total.published += s.published; + total.staged += s.staged; + total.export_failed += s.export_failed; + total.pruned_windows += s.pruned_windows; + total.max_export_ms = + std::max(total.max_export_ms, s.max_export_ms); + } + { + std::lock_guard lk(retire_mu_); + total.pending_exports = pending_exports_; + total.max_pending_exports = max_pending_exports_; + total.pending_export_bytes = pending_export_bytes_; + total.max_pending_export_bytes = max_pending_export_bytes_; + total.lost_windows = lost_windows_; + } + return total; +} + +void FileLogSink::rotateDueWindows() { + for (FileChannel* ch : {chanDevice_.get(), chanScope_.get(), + chanSystem_.get(), chanSass_.get()}) { + if (ch) ch->rotateIfDue(); + } +} + +void FileLogSink::enqueueRetired(FileChannel* channel, + const std::size_t index, + const std::uint64_t bytes) { + if (!channel) return; + std::lock_guard lk(retire_mu_); + if (retire_stop_) { + // Never export inline here: enqueueRetired() is called while the + // channel mutex is held, and exportRetired() takes that same mutex to + // fold stats, which would self-deadlock. The indexed raw file is + // already durable in `.tmp`; close-time salvage owns this rare race. + GFL_LOG_WARN("[Logger] retirement worker already stopped; leaving " + "window ", index, " in `.tmp` for salvage."); + return; + } + retire_queue_.push_back({channel, index, bytes}); + ++pending_exports_; + pending_export_bytes_ += bytes; + max_pending_exports_ = + std::max(max_pending_exports_, pending_exports_); + max_pending_export_bytes_ = + std::max(max_pending_export_bytes_, pending_export_bytes_); + if (pending_exports_ >= 8 && + (pending_exports_ & (pending_exports_ - 1)) == 0) { + GFL_LOG_WARN("[Logger] retirement export backlog: ", + pending_exports_, " window(s), ", + pending_export_bytes_, " raw byte(s) pending."); + } + if (!retire_worker_.joinable()) { + // Started on first use: a session that never rotates never pays + // for a thread. + retire_worker_ = std::thread([this] { + for (;;) { + RetiredWindow item{}; + { + std::unique_lock lk(retire_mu_); + retire_cv_.wait(lk, [this] { + return retire_stop_ || !retire_queue_.empty(); + }); + if (retire_queue_.empty()) return; // stop + drained + item = retire_queue_.front(); + retire_queue_.pop_front(); + ++exports_in_flight_; + } + // Outside every lock: gzip + publish retries live here. + item.channel->exportRetired(item.index); + { + std::lock_guard lk(retire_mu_); + --exports_in_flight_; + if (pending_exports_ > 0) --pending_exports_; + if (pending_export_bytes_ >= item.bytes) { + pending_export_bytes_ -= item.bytes; + } else { + pending_export_bytes_ = 0; + } + } + retire_cv_.notify_all(); + } + }); + } + retire_cv_.notify_one(); +} + +void FileLogSink::waitForPendingExports() { + std::unique_lock lk(retire_mu_); + retire_cv_.wait(lk, [this] { + return retire_queue_.empty() && exports_in_flight_ == 0; + }); +} + +void FileLogSink::stopRetirementWorker() { + { + std::lock_guard lk(retire_mu_); + retire_stop_ = true; + } + retire_cv_.notify_all(); + if (retire_worker_.joinable()) retire_worker_.join(); +} + void FileLogSink::close() { + // Drain and stop the worker BEFORE the channels go away: it holds raw + // channel pointers, and window indices must stop moving before each + // channel exports its final active window. + stopRetirementWorker(); if (chanDevice_) chanDevice_->close(); if (chanScope_) chanScope_->close(); if (chanSystem_) chanSystem_->close(); @@ -220,6 +465,19 @@ void FileLogSink::close() { if (!temp_dir_.empty()) { const fs::path session_dir = fs::path(temp_dir_).parent_path(); const auto salvage = salvageSessionTempDir(session_dir); + if (salvage.lost_windows > 0) { + // Terminal: those events are gone. Say so where an operator will + // see it AND keep it in the stats, because everything downstream + // (an emptied `.tmp`, a finished upload) now looks like a clean + // session. Reporting this onward is the open follow-up. + std::lock_guard lk(retire_mu_); + lost_windows_ += static_cast(salvage.lost_windows); + GFL_LOG_ERROR("[Logger] session '", session_dir.string(), "': ", + salvage.lost_windows, + " transport window(s) were unrecoverable and have " + "been discarded. Their events are LOST - the " + "uploaded session is incomplete."); + } if (salvage.deferred > 0 || sessionTempDirHasDeferredData(session_dir)) { GFL_LOG_ERROR("[Logger] session temp dir '", temp_dir_, "' still contains deferred log data (salvaged=", diff --git a/include/gpufl/core/logger/file_log_sink.hpp b/include/gpufl/core/logger/file_log_sink.hpp index f0f3d92..41c9a94 100644 --- a/include/gpufl/core/logger/file_log_sink.hpp +++ b/include/gpufl/core/logger/file_log_sink.hpp @@ -1,10 +1,14 @@ #pragma once +#include #include +#include +#include #include #include #include #include +#include #include "gpufl/core/logger/log_sink.hpp" #include "gpufl/core/logger/logger.hpp" @@ -55,29 +59,117 @@ class FileLogSink final : public ILogSink { */ bool anyChannelOpen() const; + /** + * Rotation outcomes summed across channels. An IN-MEMORY test and + * measurement seam - it is NOT durable and is not exported anywhere; + * files alone can't say WHY a window was published, and failed + * exports leave no file at all. + * + * by_size / by_time count durable CUTOVERS keyed by which trigger fired + * first. published / staged / export_failed describe the later worker + * outcome; pruned_windows counts old published windows the max_files cap + * DELETED, i.e. potential un-uploaded data loss. + */ + struct RotationStats { + // Windows CUT OVER by each trigger. A cutover is the boundary + // itself: the window is immutable and durable in `.tmp` from + // this moment, whether or not the export has run yet. + std::size_t by_size = 0; + std::size_t by_time = 0; + // Cutover blocked (a holder denied the rename): the data is still + // the active window and its age is preserved, so the next beat + // retries instead of waiting out a fresh cadence. + std::size_t cutover_blocked = 0; + // Export outcomes, counted on the retirement worker. + std::size_t published = 0; // finished file in the session root + std::size_t staged = 0; // compressed, publish blocked + std::size_t export_failed = 0; // compression failed + // Old published windows the max_files cap DELETED - potential + // un-uploaded data loss, surfaced rather than swallowed. + std::size_t pruned_windows = 0; + // Slowest single export, for sizing the compression cost that the + // worker now absorbs instead of the collector. + std::int64_t max_export_ms = 0; + // Retirement-worker backlog. Unlike max_files (published windows), + // these cover immutable raw windows still waiting for gzip/publish. + std::size_t pending_exports = 0; + std::size_t max_pending_exports = 0; + std::uint64_t pending_export_bytes = 0; + std::uint64_t max_pending_export_bytes = 0; + // Windows whose events are GONE - discarded at close() because + // nothing on disk could still yield them. Terminal, unlike + // `staged`/`export_failed`, which salvage still recovers. + std::size_t lost_windows = 0; + }; + RotationStats rotationStats() const; + + /** + * Block until every retired window has been exported. Called at + * close() before the temp dir is swept, and by tests that need the + * asynchronous export to have landed. + */ + void waitForPendingExports(); + + /** + * Rotate every channel whose non-empty window is older than + * rotate_after_ms RIGHT NOW - the deadline path for channels that + * went quiet. Called from the collector's periodic beat; without + * it the time trigger only ever fires on the next write, and a + * channel that wrote once then stalled would sit in `.tmp` + * indefinitely. No-op for empty windows (idle channels never + * publish empty files) and when the time trigger is off. + */ + void rotateDueWindows() override; + private: // One stream per channel, matching the existing file layout. class FileChannel { public: - FileChannel(std::string name, Logger::Options opt); + FileChannel(std::string name, Logger::Options opt, FileLogSink* owner); ~FileChannel(); void write(std::string_view line); void close(); bool isOpen() const; + RotationStats rotationStats() const; + void rotateIfDue(); + /** + * Compress + publish a window this channel already retired. Runs + * on the retirement worker with NO channel lock held - it only + * touches files nothing writes to any more - and takes the lock + * just to fold the outcome into the stats. + */ + void exportRetired(std::size_t index); private: void ensureOpenLocked(); - void rotateLocked(); + enum class RotateTrigger { Size, Time }; + void rotateLocked(RotateTrigger trigger); + bool timeDueLocked(std::int64_t now) const; void closeLocked(); + std::int64_t nowMs() const; std::string name_; Logger::Options opt_; + FileLogSink* owner_ = nullptr; // non-owning; outlives the channel std::unique_ptr compressor_; std::unique_ptr rotator_; std::ofstream stream_; size_t current_bytes_ = 0; + // Next window index to hand out, seeded ONCE from the filesystem and + // then owned by this channel. It must not be re-derived per rotation: + // nextWindowIndex() scans `.tmp` and the session root, and the + // retirement worker moves files between exactly those two directories + // with no lock held, so a window in flight can be missed by both + // scans - handing its index out twice, and fs::rename replaces its + // destination silently. 0 = not seeded yet. + std::size_t next_window_index_ = 0; + // Monotonic time of the current window's FIRST write; -1 = the + // window is empty. Drives the rotate_after_ms trigger: an empty + // window has no age, so it can never rotate. + std::int64_t window_first_write_ms_ = -1; + RotationStats rotation_stats_; mutable std::mutex mu_; bool opened_ = false; @@ -85,6 +177,16 @@ class FileLogSink final : public ILogSink { FileChannel* resolveChannel(Channel ch) const; + /** + * Hand a retired window to the export worker. Called from a channel + * with its lock held, so it must not block: it appends and notifies. + * Starts the worker on first use, so sessions that never rotate never + * spawn a thread. + */ + void enqueueRetired(FileChannel* channel, std::size_t index, + std::uint64_t bytes); + void stopRetirementWorker(); + std::unique_ptr chanDevice_; std::unique_ptr chanScope_; std::unique_ptr chanSystem_; @@ -92,6 +194,30 @@ class FileLogSink final : public ILogSink { // The shared session `.tmp` dir, removed once in close() after every // channel has finalized (its own actives would block earlier removal). std::string temp_dir_; + + // Retirement queue: cutover happens on whichever thread hit the + // boundary (fast, metadata-only), compression and publish retries + // happen here. Without this split a 64 MiB gzip - or 700 ms of + // publish backoff - would run inside the CUPTI collector beat or a + // writer, stalling ring drain and every other logger write. + struct RetiredWindow { + FileChannel* channel; + std::size_t index; + std::uint64_t bytes; + }; + mutable std::mutex retire_mu_; + std::condition_variable retire_cv_; + std::deque retire_queue_; + std::size_t exports_in_flight_ = 0; + std::size_t pending_exports_ = 0; + std::size_t max_pending_exports_ = 0; + std::uint64_t pending_export_bytes_ = 0; + std::uint64_t max_pending_export_bytes_ = 0; + // Sink-level like the pending_* counters (the channels are already gone + // when close() learns this): written by close(), read by rotationStats(). + std::size_t lost_windows_ = 0; + bool retire_stop_ = false; + std::thread retire_worker_; }; } // namespace gpufl diff --git a/include/gpufl/core/logger/log_rotator.cpp b/include/gpufl/core/logger/log_rotator.cpp index 5920657..0b59182 100644 --- a/include/gpufl/core/logger/log_rotator.cpp +++ b/include/gpufl/core/logger/log_rotator.cpp @@ -1,9 +1,7 @@ #include "gpufl/core/logger/log_rotator.hpp" -#include #include #include -#include #include #include @@ -44,99 +42,185 @@ std::string LogFileRotator::rotatedPath(std::size_t index) const { return oss.str(); } -LogFileRotator::ExportWindowResult LogFileRotator::exportWindow_() const { +std::string LogFileRotator::retiredPath(std::size_t index) const { + std::ostringstream oss; + oss << tempDir() << "/" << opt_.channel_name << "." << index << ".log"; + return oss.str(); +} + +std::size_t LogFileRotator::nextWindowIndex() const { + return nextLogWindowIndex(fs::path(sessionDir()), opt_.channel_name); +} + +bool LogFileRotator::publishWithRetry_(const std::string& from, + const std::string& to) const { + std::error_code ec; + // The no-replace operation closes the exists()->rename() TOCTOU window: + // a concurrent salvage/uploader can claim `to` after a pre-check. A + // collision must leave `from` visible, never replace the older window. + for (int attempt = 0; attempt < 3; ++attempt) { + const auto moved = moveFileNoReplace(from, to, ec); + if (moved == MoveFileNoReplaceResult::Moved) return true; + if (moved == MoveFileNoReplaceResult::DestinationExists) { + GFL_LOG_ERROR("[Logger] window export: refusing to publish '", + from, "' over the existing window '", to, + "' - window indices must be unique. Left in `.tmp` " + "for the salvage pass."); + return false; + } + std::this_thread::sleep_for(std::chrono::milliseconds(100 << attempt)); + } + GFL_LOG_ERROR("[Logger] window export: publish failed for '", from, "' (", + ec.message(), ") - left for the salvage pass."); + return false; +} + +LogFileRotator::RetireResult LogFileRotator::retireActiveWindow( + const std::size_t index) const { const std::string active = activePath(); std::error_code ec; - if (!fs::exists(active, ec)) return ExportWindowResult::NoData; - if (fs::file_size(active, ec) == 0) return ExportWindowResult::NoData; + if (!fs::exists(active, ec)) return RetireResult::NoData; + if (fs::file_size(active, ec) == 0) return RetireResult::NoData; + + // Same reasoning as publishWithRetry_: claim the retired name atomically. + // A pre-check followed by rename still permits another actor to create + // the destination between the two operations. + const auto retired = + moveFileNoReplace(active, retiredPath(index), ec); + if (retired == MoveFileNoReplaceResult::DestinationExists) { + GFL_LOG_ERROR("[Logger] window cutover: index ", index, + " is already taken by '", retiredPath(index), + "' - refusing to overwrite it."); + return RetireResult::Blocked; + } + if (retired != MoveFileNoReplaceResult::Moved) { + GFL_LOG_ERROR("[Logger] window cutover: could not retire '", active, + "' (", ec.message(), + ") - the data stays in the active window and the next " + "beat retries."); + return RetireResult::Blocked; + } + return RetireResult::Retired; +} - // Append-style monotonic index (higher = newer). Published files and - // unpublished .tmp staging both count, so a failed publish cannot be - // overwritten by the next rotation. - const std::size_t next = - nextLogWindowIndex(fs::path(sessionDir()), opt_.channel_name); +LogFileRotator::ExportWindowResult LogFileRotator::exportRetiredWindow( + const std::size_t index, std::size_t* pruned_windows) const { + const std::string retired = retiredPath(index); + std::error_code ec; + if (!fs::exists(retired, ec)) return ExportWindowResult::NoData; + + const auto prune = [&]() { + const std::size_t removed = pruneLogWindows( + fs::path(sessionDir()), opt_.channel_name, opt_.max_files); + if (removed > 0) { + if (pruned_windows) *pruned_windows += removed; + GFL_LOG_ERROR("[Logger] window cap (max_files=", opt_.max_files, + ") deleted ", removed, " old '", opt_.channel_name, + "' window(s) that may not have been uploaded yet. " + "Raise max_files or drain windows faster."); + } + }; if (!compressor_) { - const std::string target = rotatedPath(next); - fs::rename(active, target, ec); - if (ec) { - GFL_LOG_ERROR("[Logger] window export: publish failed for '", - active, "' (", ec.message(), - ") - deferred in the active file."); - return ExportWindowResult::DeferredInActive; + if (!publishWithRetry_(retired, rotatedPath(index))) { + // The retired file is still in `.tmp`, indexed and complete - + // the salvage pass publishes it. + return ExportWindowResult::StagedForSalvage; } - pruneLogWindows(fs::path(sessionDir()), opt_.channel_name, - opt_.max_files); + prune(); return ExportWindowResult::Published; } - const std::string target = rotatedPath(next) + ".gz"; - std::ostringstream stg; - stg << tempDir() << "/" << opt_.channel_name << "." << next << ".log.gz"; - const std::string staging = stg.str(); - - // 1. gzip the active file into staging (inside .tmp) - a pure READ of - // the active file, immune to holders. The session root never sees a - // partial file. - if (!compressor_->compressTo(active, staging)) { + const std::string staging = retired + ".gz"; + const std::string partial = staging + ".part"; + // A name ending in `.part` is deliberately NOT a transport window. + // `compressTo` closes and validates the gzip before the atomic rename + // below makes it visible to salvage. A crash during compression leaves + // the raw authoritative source plus an explicitly incomplete artifact. + // + // SCOPE: this is PROCESS-CRASH safe (SIGKILL, an unhandled fault, a + // teardown that never runs shutdown) - at every point the window's bytes + // exist in exactly one place salvage can name. It is NOT power-loss + // durable: nothing here fsyncs the gzip or the directory, so a rename + // can reach the disk before the data it names. Salvage is defensive + // about that (it re-validates every gzip and rejects empty or truncated + // ones) but the guarantee itself needs file sync -> rename -> directory + // sync, which is not implemented. + fs::remove(partial, ec); + if (!compressor_->compressTo(retired, partial)) { std::error_code rm_ec; - fs::remove(staging, rm_ec); - GFL_LOG_ERROR("[Logger] window export: compress failed for '", active, - "' - deferred to the next write."); + fs::remove(partial, rm_ec); + GFL_LOG_ERROR("[Logger] window export: compress failed for '", retired, + "' - left in `.tmp` for the salvage pass."); return ExportWindowResult::DeferredInActive; } - // 2. Truncate the active file BEFORE publishing the export: if this - // is denied (holder without write sharing - rare), drop staging and - // defer. The data then exists exactly once, in the active file. - { - std::ofstream trunc(active, std::ios::out | std::ios::trunc); - if (!trunc) { - std::error_code rm_ec; - fs::remove(staging, rm_ec); - GFL_LOG_ERROR("[Logger] window export: truncate denied for '", - active, "' - deferred to the next write."); - return ExportWindowResult::DeferredInActive; - } + fs::rename(partial, staging, ec); + if (ec) { + std::error_code rm_ec; + fs::remove(partial, rm_ec); + GFL_LOG_ERROR("[Logger] window export: could not promote completed " + "gzip '", partial, "' to '", staging, "' (", + ec.message(), ") - raw source remains authoritative."); + return ExportWindowResult::StagedForSalvage; } - // 3. Publish: staging → ..log.gz in the session root. - // Consumers only ever see the finished file. If the rename is blocked - // (AV grabbing brand-new files), the data survives in staging and the - // launcher's salvage pass publishes it later. - bool published = false; - for (int attempt = 0; attempt < 3; ++attempt) { - fs::rename(staging, target, ec); - if (!ec) { - published = true; - break; - } - std::this_thread::sleep_for(std::chrono::milliseconds(100 << attempt)); - } - if (!published) { - GFL_LOG_ERROR("[Logger] window export: publish failed for '", staging, - "' (", ec.message(), - ") - left for the salvage pass."); + // The completed staging gzip is now authoritative only after the raw + // source is gone or empty. Never publish both: shutdown salvage would + // otherwise assign the leftover raw a new index and duplicate every row. + if (!removeOrTruncateFile(retired)) { + GFL_LOG_ERROR("[Logger] window export: completed gzip '", staging, + "' but could not remove or truncate raw source '", + retired, "' - left both in `.tmp` for exact-once " + "salvage reconciliation."); return ExportWindowResult::StagedForSalvage; } - pruneLogWindows(fs::path(sessionDir()), opt_.channel_name, opt_.max_files); + if (!publishWithRetry_(staging, rotatedPath(index) + ".gz")) { + return ExportWindowResult::StagedForSalvage; + } + prune(); return ExportWindowResult::Published; } -void LogFileRotator::rotate() const { exportWindow_(); } +LogFileRotator::ExportWindowResult LogFileRotator::exportWindow_( + std::size_t* pruned_windows) const { + return exportWindowAt_(nextWindowIndex(), pruned_windows); +} + +LogFileRotator::ExportWindowResult LogFileRotator::exportWindowAt_( + const std::size_t index, std::size_t* pruned_windows) const { + switch (retireActiveWindow(index)) { + case RetireResult::NoData: + return ExportWindowResult::NoData; + case RetireResult::Blocked: + return ExportWindowResult::DeferredInActive; + case RetireResult::Retired: + // Shutdown uses the same crash-safe raw -> .part -> completed + // gzip transaction as mid-run retirement; only the thread differs. + return exportRetiredWindow(index, pruned_windows); + } + return ExportWindowResult::DeferredInActive; +} + +LogFileRotator::ExportWindowResult LogFileRotator::rotate( + std::size_t* pruned_windows) const { + return exportWindow_(pruned_windows); +} -void LogFileRotator::compressActive() const { - const ExportWindowResult result = exportWindow_(); +LogFileRotator::ExportWindowResult LogFileRotator::compressActive( + const std::size_t index) const { + const ExportWindowResult result = exportWindowAt_(index, nullptr); // Best-effort removal of this channel's (now exported) active file. // If exportWindow_ deferred in the active file, leave it for the salvage // path instead of deleting the only copy of the window. - if (result == ExportWindowResult::DeferredInActive) return; + if (result == ExportWindowResult::DeferredInActive) return result; // The shared .tmp dir itself is removed once by FileLogSink::close() // after EVERY channel has closed - other channels' actives are still // open while the first one finalizes. std::error_code ec; fs::remove(activePath(), ec); + return result; } diff --git a/include/gpufl/core/logger/log_rotator.hpp b/include/gpufl/core/logger/log_rotator.hpp index cf12fac..2ec7167 100644 --- a/include/gpufl/core/logger/log_rotator.hpp +++ b/include/gpufl/core/logger/log_rotator.hpp @@ -30,8 +30,31 @@ struct LogRotationOptions { class LogFileRotator { public: + /** + * What actually happened to the window. Callers must branch on this - + * treating every rotate() as a success once double-counted stats, + * reset the window age on a DEFERRED export (delaying the retry by a + * full cadence), and hid real publish failures. + */ + enum class ExportWindowResult { + NoData, // active file empty/missing - nothing exported + Published, // window is a finished file in the session root + StagedForSalvage, // exported into .tmp staging; publish rename + // failed - the salvage pass finishes it. The + // active file WAS truncated: a new window began. + DeferredInActive, // compress/truncate failed - the data is still + // the active file's current window. Retry later. + }; + LogFileRotator(LogRotationOptions opt, IFileCompressor* compressor); + /** Outcome of the fast cutover half of a rotation. */ + enum class RetireResult { + NoData, // active file empty/missing - no window to retire + Retired, // active window is now an immutable `.tmp/..log` + Blocked, // rename denied (a holder) - data stays the active window + }; + /** * The active file lives in the session's TEMP subdir * (`/.tmp/.log`), never in the session root. The @@ -44,18 +67,49 @@ class LogFileRotator { [[nodiscard]] std::string activePath() const; /** - * Export the current window. The active file is never renamed or - * deleted - operations on it are limited to READ (gzip) and TRUNCATE, - * which work even while another process holds the file: - * 1. gzip active → `.tmp/..log.gz` (staging, pure read) - * 2. truncate active (restart the window) - * 3. move staging → `/..log.gz` (fresh name at - * a monotonic index - no shifting, no overwrite hazard) - * Any failed step logs and defers: data stays exactly-once (in the - * active file or in staging, both inside `.tmp`, which consumers - * ignore), and the next write or the launcher's salvage pass retries. + * Export the current window synchronously for shutdown: retire the + * active file to an indexed raw window, compress through an unrecognized + * `.part` artifact, atomically promote the completed gzip, remove or + * truncate the raw authority, then publish. This is the same crash-safe + * transaction used by the asynchronous mid-run path. + * + * `pruned_windows` (optional out): how many OLD published windows the + * max_files cap deleted while publishing this one - un-uploaded data + * loss the caller must surface, not swallow. + * + * SYNCHRONOUS - compression and publish retries happen on the calling + * thread. Used by the shutdown path only. Mid-run rotation splits this + * into retireActiveWindow() + exportRetiredWindow() so no collector or + * writer thread ever waits on gzip. */ - void rotate() const; + ExportWindowResult rotate(std::size_t* pruned_windows = nullptr) const; + + /** Next append-style window index for this channel (root + `.tmp`). */ + [[nodiscard]] std::size_t nextWindowIndex() const; + + /** + * Fast half of a rotation: rename the active file to an immutable + * `.tmp/..log`. Metadata-only, so it is safe to call + * under the channel lock from the collector beat or a writer. + * + * A retired file is durable and self-describing: if the process dies + * before it is exported, the salvage pass compresses and publishes it + * (log_salvage.cpp handles plain indexed windows in `.tmp`). + * + * `Blocked` (a holder denied the rename) leaves the data as the + * current active window - the caller keeps the window's age so the + * next beat retries rather than waiting out a fresh cadence. + */ + RetireResult retireActiveWindow(std::size_t index) const; + + /** + * Slow half: compress the retired window and publish it into the + * session root, then prune. Touches only files nothing writes to any + * more, so it runs off the caller's thread with no lock held; the + * publish retry/backoff for transient holders lives here. + */ + ExportWindowResult exportRetiredWindow(std::size_t index, + std::size_t* pruned_windows) const; /** * Finalize this channel on clean shutdown (FileLogSink::close → @@ -66,7 +120,13 @@ class LogFileRotator { * On crash (shutdown never runs) the active `.log` stays in `.tmp` - * the launcher repair / uploader salvage exports it on first sight. */ - void compressActive() const; + /** + * Finalize the active window using the index owned by FileChannel. + * The shutdown path must not re-scan the filesystem: published files may + * already have been acknowledged and removed, but their indices remain + * consumed for the lifetime of the session. + */ + ExportWindowResult compressActive(std::size_t index) const; /** * The session temp dir: `//.tmp`. Removed @@ -81,16 +141,16 @@ class LogFileRotator { */ [[nodiscard]] std::string sessionDir() const; [[nodiscard]] std::string rotatedPath(std::size_t index) const; - - enum class ExportWindowResult { - NoData, - Published, - StagedForSalvage, - DeferredInActive, - }; + /** A retired-but-not-yet-exported window: `.tmp/..log`. */ + [[nodiscard]] std::string retiredPath(std::size_t index) const; + /** staging → session root, with backoff for transient holders. */ + [[nodiscard]] bool publishWithRetry_(const std::string& from, + const std::string& to) const; /** Shared body of rotate()/compressActive(). */ - ExportWindowResult exportWindow_() const; + ExportWindowResult exportWindow_(std::size_t* pruned_windows) const; + ExportWindowResult exportWindowAt_(std::size_t index, + std::size_t* pruned_windows) const; LogRotationOptions opt_; IFileCompressor* compressor_ = nullptr; // non-owning diff --git a/include/gpufl/core/logger/log_salvage.cpp b/include/gpufl/core/logger/log_salvage.cpp index 9d2c457..61f5dcc 100644 --- a/include/gpufl/core/logger/log_salvage.cpp +++ b/include/gpufl/core/logger/log_salvage.cpp @@ -1,11 +1,39 @@ #include "gpufl/core/logger/log_salvage.hpp" #include +#include +#include +#include +#include +#include +#include #include #include +#include #include +#include #include +#include + +#if defined(_WIN32) +#ifndef NOMINMAX +#define NOMINMAX +#endif +#include +#else +#include +#include +#if defined(__linux__) +#include +#include +#ifndef RENAME_NOREPLACE +#define RENAME_NOREPLACE (1 << 0) +#endif +#endif +#endif + +#include "gpufl/core/debug_logger.hpp" #include "gpufl/core/logger/file_compressor.hpp" namespace gpufl { @@ -87,13 +115,277 @@ std::vector publishedWindowIndices(const fs::path& session_dir, return {indices.begin(), indices.end()}; } -bool removeOrTruncate(const fs::path& p) { - std::error_code ec; - fs::remove(p, ec); - if (!ec || !fs::exists(p, ec)) return true; +bool endsWith(const std::string& value, const std::string& suffix) { + return value.size() >= suffix.size() && + value.compare(value.size() - suffix.size(), suffix.size(), + suffix) == 0; +} + +} // namespace + +MoveFileNoReplaceResult moveFileNoReplace(const fs::path& from, + const fs::path& to, + std::error_code& ec) { + ec.clear(); +#if defined(_WIN32) + // MoveFileEx without MOVEFILE_REPLACE_EXISTING is the Windows atomic + // no-clobber primitive. Do not request WRITE_THROUGH here: the cutover + // path runs on the collector/writer and is intentionally metadata-only. + if (::MoveFileExW(from.c_str(), to.c_str(), 0)) { + return MoveFileNoReplaceResult::Moved; + } + const DWORD error = ::GetLastError(); + ec = std::error_code(static_cast(error), std::system_category()); + if (error == ERROR_FILE_EXISTS || error == ERROR_ALREADY_EXISTS) { + return MoveFileNoReplaceResult::DestinationExists; + } + return MoveFileNoReplaceResult::Failed; +#else +#if defined(__linux__) && defined(SYS_renameat2) + if (::syscall(SYS_renameat2, AT_FDCWD, from.c_str(), AT_FDCWD, to.c_str(), + RENAME_NOREPLACE) == 0) { + return MoveFileNoReplaceResult::Moved; + } + const int rename_error = errno; + if (rename_error == EEXIST) { + ec = std::error_code(rename_error, std::generic_category()); + return MoveFileNoReplaceResult::DestinationExists; + } + // Older kernels/filesystems may not implement renameat2. Fall back to an + // atomic destination claim with link(2); all spool moves stay on the same + // session filesystem. + if (rename_error != ENOSYS && rename_error != EINVAL && + rename_error != EOPNOTSUPP) { + ec = std::error_code(rename_error, std::generic_category()); + return MoveFileNoReplaceResult::Failed; + } +#endif + if (::link(from.c_str(), to.c_str()) != 0) { + const int link_error = errno; + ec = std::error_code(link_error, std::generic_category()); + return link_error == EEXIST + ? MoveFileNoReplaceResult::DestinationExists + : MoveFileNoReplaceResult::Failed; + } + if (::unlink(from.c_str()) == 0) { + return MoveFileNoReplaceResult::Moved; + } + // The destination is already a hard link to the same complete bytes. Keep + // both names visible for salvage rather than pretending the move finished. + ec = std::error_code(errno, std::generic_category()); + return MoveFileNoReplaceResult::Failed; +#endif +} + +bool isValidGzipFile(const fs::path& path) { + // A zero-length file is not a window, and zlib will not say so: gzread + // reports EOF-on-first-read as a clean read with Z_OK, so an empty file + // would validate. That mattered: a rename publishes a directory entry + // before the data is necessarily durable, so a power loss right after + // `.part` -> `.gz` can leave an empty `.gz` next to its still-complete + // raw source. Validating it would delete the raw as a duplicate and + // publish the empty file as the window - silent loss of a full window. + // (A NON-empty truncated gzip is caught by the decode below.) + std::error_code size_ec; + const auto size = fs::file_size(path, size_ec); + if (size_ec || size == 0) return false; + + gzFile file = gzopen(path.string().c_str(), "rb"); + if (!file) return false; + + bool ok = true; + char buffer[64 * 1024]; + int read = 0; + while ((read = gzread(file, buffer, sizeof(buffer))) > 0) { + } + if (read < 0) ok = false; + + int zerr = Z_OK; + (void)gzerror(file, &zerr); + if (zerr != Z_OK && zerr != Z_STREAM_END) ok = false; + if (gzclose(file) != Z_OK) ok = false; + return ok; +} + +namespace { + +constexpr const char* kTransportLossPrefix = ".gpufl-transport-loss."; +constexpr const char* kTransportLossSuffix = ".json"; + +bool isTransportLossMarker(const fs::path& path) { + const std::string name = path.filename().string(); + return name.size() > + std::strlen(kTransportLossPrefix) + + std::strlen(kTransportLossSuffix) && + name.compare(0, std::strlen(kTransportLossPrefix), + kTransportLossPrefix) == 0 && + name.compare(name.size() - std::strlen(kTransportLossSuffix), + std::strlen(kTransportLossSuffix), + kTransportLossSuffix) == 0; +} + +std::string markerSafe(std::string value) { + for (char& c : value) { + const unsigned char uc = static_cast(c); + if (!std::isalnum(uc) && c != '_' && c != '-') c = '_'; + } + return value.empty() ? "unknown" : value; +} + +std::string jsonEscape(const std::string& value) { + std::string escaped; + escaped.reserve(value.size()); + for (const char c : value) { + switch (c) { + case '\\': + escaped += "\\\\"; + break; + case '"': + escaped += "\\\""; + break; + case '\n': + escaped += "\\n"; + break; + case '\r': + escaped += "\\r"; + break; + case '\t': + escaped += "\\t"; + break; + default: + escaped += c; + break; + } + } + return escaped; +} + +bool recordTransportLoss(const fs::path& session_dir, + const std::string& channel, + const std::size_t index, + const std::string& reason) { + const fs::path marker = + session_dir / + (std::string(kTransportLossPrefix) + markerSafe(channel) + "." + + std::to_string(index) + kTransportLossSuffix); + std::error_code state_ec; + if (fs::exists(marker, state_ec)) return true; + + static std::atomic nonce{0}; + const auto tick = std::chrono::steady_clock::now() + .time_since_epoch() + .count(); + const fs::path partial = + fs::path(marker.string() + ".part." + std::to_string(tick) + "." + + std::to_string(nonce.fetch_add(1, std::memory_order_relaxed))); + { + std::ofstream out(partial, std::ios::binary | std::ios::trunc); + if (!out) return false; + out << "{\"schema_version\":1,\"type\":\"transport_window_loss\"," + "\"channel\":\"" + << jsonEscape(channel) << "\",\"window_index\":" << index + << ",\"reason\":\"" << jsonEscape(reason) << "\"}\n"; + out.flush(); + if (!out) { + out.close(); + std::error_code rm_ec; + fs::remove(partial, rm_ec); + return false; + } + } + + std::error_code move_ec; + const auto moved = moveFileNoReplace(partial, marker, move_ec); + if (moved == MoveFileNoReplaceResult::Moved || + moved == MoveFileNoReplaceResult::DestinationExists) { + std::error_code rm_ec; + fs::remove(partial, rm_ec); + return true; + } + std::error_code rm_ec; + fs::remove(partial, rm_ec); + GFL_LOG_ERROR("[Logger] could not persist transport-loss marker '", + marker.string(), "' (", move_ec.message(), + "); preserving the damaged artifact instead."); + return false; +} + +bool gzipPayloadsEqual(const fs::path& lhs, const fs::path& rhs) { + gzFile a = gzopen(lhs.string().c_str(), "rb"); + gzFile b = gzopen(rhs.string().c_str(), "rb"); + if (!a || !b) { + if (a) (void)gzclose(a); + if (b) (void)gzclose(b); + return false; + } + + std::array a_buf{}; + std::array b_buf{}; + bool same = true; + for (;;) { + const int a_read = + gzread(a, a_buf.data(), static_cast(a_buf.size())); + const int b_read = + gzread(b, b_buf.data(), static_cast(b_buf.size())); + if (a_read < 0 || b_read < 0 || a_read != b_read) { + same = false; + break; + } + if (a_read == 0) break; + if (std::memcmp(a_buf.data(), b_buf.data(), + static_cast(a_read)) != 0) { + same = false; + break; + } + } + if (gzclose(a) != Z_OK) same = false; + if (gzclose(b) != Z_OK) same = false; + return same; +} + +bool rawMatchesGzipPayload(const fs::path& raw, const fs::path& gzip) { + std::ifstream in(raw, std::ios::binary); + gzFile gz = gzopen(gzip.string().c_str(), "rb"); + if (!in || !gz) { + if (gz) (void)gzclose(gz); + return false; + } - std::ofstream trunc(p, std::ios::out | std::ios::trunc); - return static_cast(trunc); + std::array raw_buf{}; + std::array gz_buf{}; + bool same = true; + for (;;) { + in.read(raw_buf.data(), static_cast(raw_buf.size())); + const auto raw_read = in.gcount(); + const int gz_read = + gzread(gz, gz_buf.data(), static_cast(gz_buf.size())); + if (gz_read < 0 || raw_read != gz_read) { + same = false; + break; + } + if (raw_read == 0) { + if (in.bad()) same = false; + break; + } + if (std::memcmp(raw_buf.data(), gz_buf.data(), + static_cast(raw_read)) != 0) { + same = false; + break; + } + } + if (gzclose(gz) != Z_OK) same = false; + return same; +} + +std::vector regularFiles(const fs::path& dir) { + std::vector entries; + std::error_code ec; + for (const auto& entry : fs::directory_iterator(dir, ec)) { + std::error_code e_ec; + if (entry.is_regular_file(e_ec)) entries.push_back(entry.path()); + } + std::sort(entries.begin(), entries.end()); + return entries; } bool tempDirHasDeferredData(const fs::path& tmp) { @@ -120,47 +412,200 @@ void removeTempDirIfClean(const fs::path& tmp) { } // namespace +std::size_t transportLossMarkerCount(const fs::path& session_dir) { + std::size_t count = 0; + std::error_code ec; + if (!fs::exists(session_dir, ec) || !fs::is_directory(session_dir, ec)) { + return 0; + } + for (const auto& entry : fs::directory_iterator(session_dir, ec)) { + std::error_code entry_ec; + if (entry.is_regular_file(entry_ec) && + isTransportLossMarker(entry.path())) { + ++count; + } + } + return count; +} + std::size_t nextLogWindowIndex(const fs::path& session_dir, const std::string& channel) { + // Scan `.tmp` FIRST, the session root SECOND - the reverse of the + // direction a window travels when it is published. A window renamed + // `.tmp` -> root between the two scans is then counted TWICE (harmless) + // instead of zero times (which would hand its index out again, and + // fs::rename replaces its destination silently). + // + // Order alone is not sufficient protection, only cheap: the live + // rotation path allocates from a per-channel counter (FileChannel), so + // it never re-derives an index from a directory a worker is mutating. + // This scan remains the seed for that counter and the allocator for the + // single-threaded salvage/launcher paths. std::size_t max_index = 0; - scanMaxIndex(session_dir, channel, max_index); scanMaxIndex(session_dir / ".tmp", channel, max_index); + scanMaxIndex(session_dir, channel, max_index); return max_index + 1; } -void pruneLogWindows(const fs::path& session_dir, - const std::string& channel, - const std::size_t max_files) { - if (max_files == 0) return; +std::size_t pruneLogWindows(const fs::path& session_dir, + const std::string& channel, + const std::size_t max_files) { + if (max_files == 0) return 0; auto indices = publishedWindowIndices(session_dir, channel); - if (indices.size() <= max_files) return; + if (indices.size() <= max_files) return 0; const std::size_t remove_count = indices.size() - max_files; + std::size_t removed = 0; for (std::size_t i = 0; i < remove_count; ++i) { const auto idx = indices[i]; const fs::path base = session_dir / (channel + "." + std::to_string(idx) + ".log"); std::error_code ec; - fs::remove(base, ec); - fs::remove(base.string() + ".gz", ec); + const bool got_log = fs::remove(base, ec); + std::error_code gz_ec; + const bool got_gz = fs::remove(base.string() + ".gz", gz_ec); + if (got_log || got_gz) ++removed; } + return removed; } LogSalvageResult salvageSessionTempDir(const fs::path& session_dir) { LogSalvageResult result; + // A prior pass may already have discarded an unrecoverable artifact. + // Count the durable marker even when `.tmp` is gone so an uploader that + // starts later cannot mistake the now-clean directory for a complete + // session. + result.lost_windows = + static_cast(transportLossMarkerCount(session_dir)); const fs::path tmp = session_dir / ".tmp"; std::error_code ec; if (!fs::exists(tmp, ec) || !fs::is_directory(tmp, ec)) return result; - std::vector entries; - for (const auto& entry : fs::directory_iterator(tmp, ec)) { - std::error_code e_ec; - if (entry.is_regular_file(e_ec)) entries.push_back(entry.path()); + GzipFileCompressor compressor; + std::set skip; + + // A worker compresses to `.gz.part` and atomically renames it to `.gz` + // only after gzclose succeeds. A crash can therefore leave raw + part; + // the raw file is authoritative and the incomplete part is disposable. + // A part with neither raw nor completed gzip has no trustworthy source, + // so keep it visible and report deferred instead of guessing. + for (const auto& path : regularFiles(tmp)) { + const std::string name = path.filename().string(); + if (!endsWith(name, ".log.gz.part")) continue; + + const fs::path completed = + fs::path(path.string().substr(0, path.string().size() - 5)); + const fs::path raw = + fs::path(path.string().substr(0, path.string().size() - 8)); + std::error_code state_ec; + if (fs::exists(raw, state_ec) || fs::exists(completed, state_ec)) { + std::error_code rm_ec; + if (!fs::remove(path, rm_ec) && fs::exists(path, state_ec)) { + ++result.deferred; + skip.insert(path); + } + } else { + GFL_LOG_ERROR("[Logger] salvage found orphan partial gzip '", + path.string(), + "' with no raw or completed source; leaving it for " + "manual recovery."); + ++result.deferred; + skip.insert(path); + } + } + + auto entries = regularFiles(tmp); + + // Reconcile the only intentional two-file transition: a completed, + // validated gzip may coexist briefly with its raw source while the worker + // removes/truncates the raw. Prefer the gzip, but never publish it until + // the raw is gone or empty. If the gzip is corrupt, discard it only when + // the complete raw source still exists. + for (const auto& path : entries) { + if (skip.count(path) != 0) continue; + std::string channel; + std::size_t idx = 0; + bool compressed = false; + if (!parseWindowName(path.filename().string(), channel, idx, + compressed) || + !compressed) { + continue; + } + + const fs::path raw = + fs::path(path.string().substr(0, path.string().size() - 3)); + std::error_code state_ec; + const bool raw_exists = + fs::exists(raw, state_ec) && fs::is_regular_file(raw, state_ec); + // EXISTS is not RECOVERABLE. removeOrTruncateFile deliberately leaves + // a zero-byte husk when it cannot unlink (a holder on Windows), so a + // raw file can be present and carry nothing. Treating a husk as "the + // complete raw source" would authorise deleting a corrupt-but-partly + // readable gzip - the only remaining copy of that window. + std::error_code raw_size_ec; + const bool raw_recoverable = + raw_exists && fs::file_size(raw, raw_size_ec) > 0 && !raw_size_ec; + if (!isValidGzipFile(path)) { + std::error_code size_ec; + const auto gz_size = fs::file_size(path, size_ec); + // An EMPTY artifact can never carry a window, so there is nothing + // to preserve even when no raw source is left. Dropping it + // matters: `.tmp` is the "session still writing" signal, and a + // permanently deferred zero-byte file would pin it forever, so + // the session would never look finished to the uploader or agent. + const bool empty_artifact = !size_ec && gz_size == 0; + if (raw_recoverable) { + GFL_LOG_ERROR("[Logger] salvage refused corrupt/incomplete " + "gzip '", path.string(), + "' - recovering it from the raw source."); + } else if (empty_artifact) { + GFL_LOG_ERROR("[Logger] salvage discarded an EMPTY window " + "artifact '", path.string(), + "' with no recoverable raw source. The events " + "in that window are LOST."); + } else { + // Non-empty but undecodable, with no usable raw: the bytes + // may still be partly recoverable by hand, so keep them and + // let `.tmp` stay - a visibly unfinished session beats + // deleting the last copy. + GFL_LOG_ERROR("[Logger] salvage kept corrupt gzip '", + path.string(), + "' for manual recovery - its raw source is gone " + "or empty, so this is the only copy left."); + } + bool loss_recorded = true; + if (empty_artifact && !raw_recoverable) { + // Persist BEFORE deleting the last artifact. If the marker + // cannot be made durable, leave the empty file deferred: an + // unfinished session is preferable to invisible loss. + loss_recorded = recordTransportLoss( + session_dir, channel, idx, "empty_gzip_no_raw"); + } + if ((raw_recoverable || empty_artifact) && loss_recorded) { + std::error_code rm_ec; + fs::remove(path, rm_ec); + if (!rm_ec || !fs::exists(path, state_ec)) { + continue; // the recoverable raw (if any) is salvaged + } + if (raw_recoverable) skip.insert(raw); + } + ++result.deferred; + skip.insert(path); + continue; + } + + if (raw_exists && !removeOrTruncateFile(raw.string())) { + GFL_LOG_ERROR("[Logger] salvage has a complete gzip '", + path.string(), "' but could not remove/truncate its " + "duplicate raw source '", raw.string(), "'."); + ++result.deferred; + skip.insert(path); + skip.insert(raw); + } } - std::sort(entries.begin(), entries.end()); - GzipFileCompressor compressor; bool staged_publish_blocked = false; for (const auto& path : entries) { + if (skip.count(path) != 0) continue; std::error_code e_ec; if (!fs::exists(path, e_ec) || !fs::is_regular_file(path, e_ec)) { continue; @@ -181,13 +626,44 @@ LogSalvageResult salvageSessionTempDir(const fs::path& session_dir) { session_dir / (channel + "." + std::to_string(idx) + ".log.gz"); if (fs::exists(target, e_ec)) { - idx = nextLogWindowIndex(session_dir, channel); - target = session_dir / - (channel + "." + std::to_string(idx) + ".log.gz"); + if (isValidGzipFile(target)) { + // Same index does NOT imply same window: an allocator + // race can produce two different payloads. Only discard a + // byte-for-byte decoded duplicate. A distinct payload is + // preserved for explicit reindex/recovery. + if (gzipPayloadsEqual(path, target)) { + std::error_code rm_ec; + fs::remove(path, rm_ec); + if (rm_ec && fs::exists(path, e_ec)) { + ++result.deferred; + } + } else { + GFL_LOG_ERROR( + "[Logger] salvage found TWO DIFFERENT windows " + "claiming index ", + idx, " for channel '", channel, + "'. Preserving the staged copy '", path.string(), + "'; automatic deletion would lose data."); + ++result.deferred; + skip.insert(path); + } + continue; + } + GFL_LOG_ERROR("[Logger] salvage target already exists but is " + "not a valid gzip: '", target.string(), "'."); + ++result.deferred; + continue; } std::error_code mv_ec; - fs::rename(path, target, mv_ec); - if (mv_ec) { + const auto moved = moveFileNoReplace(path, target, mv_ec); + if (moved != MoveFileNoReplaceResult::Moved) { + if (moved == MoveFileNoReplaceResult::DestinationExists) { + GFL_LOG_ERROR( + "[Logger] salvage publish collision for '", + target.string(), + "'; preserving the staged window instead of " + "overwriting it."); + } ++result.deferred; staged_publish_blocked = true; } else { @@ -213,19 +689,68 @@ LogSalvageResult salvageSessionTempDir(const fs::path& session_dir) { continue; } - idx = nextLogWindowIndex(session_dir, channel); + if (idx > 0) { + const fs::path same_index_target = + session_dir / + (channel + "." + std::to_string(idx) + ".log.gz"); + if (fs::exists(same_index_target, e_ec)) { + if (isValidGzipFile(same_index_target)) { + if (!rawMatchesGzipPayload(path, same_index_target)) { + GFL_LOG_ERROR( + "[Logger] salvage found a raw window and a " + "DIFFERENT published window at index ", + idx, " for channel '", channel, + "'. Preserving the raw copy for recovery."); + ++result.deferred; + skip.insert(path); + } else if (!removeOrTruncateFile(path.string())) { + ++result.deferred; + } + continue; + } + GFL_LOG_ERROR("[Logger] salvage found raw window '", + path.string(), "' but its published target is " + "corrupt: '", same_index_target.string(), "'."); + ++result.deferred; + continue; + } + } else { + idx = nextLogWindowIndex(session_dir, channel); + } const fs::path target = session_dir / (channel + "." + std::to_string(idx) + ".log.gz"); - if (!compressor.compressTo(path.string(), target.string())) { + const fs::path staging = path.string() + ".gz"; + const fs::path partial = staging.string() + ".part"; + if (!compressor.compressTo(path.string(), partial.string())) { ++result.deferred; std::error_code rm_ec; - fs::remove(target, rm_ec); + fs::remove(partial, rm_ec); + continue; + } + std::error_code promote_ec; + fs::rename(partial, staging, promote_ec); + if (promote_ec) { + ++result.deferred; + std::error_code rm_ec; + fs::remove(partial, rm_ec); + continue; + } + if (!removeOrTruncateFile(path.string())) { + ++result.deferred; + continue; + } + std::error_code publish_ec; + const auto published = + moveFileNoReplace(staging, target, publish_ec); + if (published != MoveFileNoReplaceResult::Moved) { + ++result.deferred; continue; } ++result.salvaged; - if (!removeOrTruncate(path)) ++result.deferred; } + result.lost_windows = + static_cast(transportLossMarkerCount(session_dir)); if (result.deferred == 0) { removeTempDirIfClean(tmp); } @@ -244,6 +769,7 @@ LogSalvageResult salvageSessionTempDirs(const fs::path& root) { const auto r = salvageSessionTempDir(session.path()); total.salvaged += r.salvaged; total.deferred += r.deferred; + total.lost_windows += r.lost_windows; } return total; } diff --git a/include/gpufl/core/logger/log_salvage.hpp b/include/gpufl/core/logger/log_salvage.hpp index 63bf1c8..bdc23c3 100644 --- a/include/gpufl/core/logger/log_salvage.hpp +++ b/include/gpufl/core/logger/log_salvage.hpp @@ -3,14 +3,72 @@ #include #include #include +#include namespace gpufl { struct LogSalvageResult { + /** Windows published into the session directory by this pass. */ int salvaged = 0; + /** + * Artifacts left in `.tmp` for a later pass or for manual recovery. + * Nonzero keeps `.tmp` alive, so the session still looks unfinished - + * that is the point: the data may still be recoverable. + */ int deferred = 0; + /** + * Windows whose events are GONE and can never be recovered, so the + * artifact was discarded to let the session finish. A TERMINAL state, + * deliberately not folded into `deferred` (which would pin `.tmp` + * forever) and never into `salvaged`. Callers must surface it: an + * unreported loss here looks exactly like a clean session downstream. + */ + int lost_windows = 0; }; +/** + * Result of moving one completed spool artifact into its published name + * without ever replacing an existing destination. + */ +enum class MoveFileNoReplaceResult { + Moved, + DestinationExists, + Failed, +}; + +/** + * Atomically claim `to` and move `from` there without replacement. + * + * `std::filesystem::rename` replaces an existing destination on POSIX and + * therefore cannot enforce the transport-window uniqueness contract. This + * helper uses a platform no-replace primitive (or a same-filesystem + * hard-link/unlink fallback) so a concurrent publisher degrades to a visible + * collision instead of destroying the older window. + */ +MoveFileNoReplaceResult moveFileNoReplace( + const std::filesystem::path& from, + const std::filesystem::path& to, + std::error_code& ec); + +/** + * True when `path` is a non-empty file that decodes cleanly as gzip all the + * way to EOF. Existence is NOT proof: a zero-length file decodes as a clean + * empty stream, and a truncated one only fails partway through - so any code + * about to delete a raw source because "the .gz is already there" must ask + * this first. + */ +bool isValidGzipFile(const std::filesystem::path& path); + +/** + * Count durable terminal-loss markers in one session directory. + * + * Markers deliberately live outside `.tmp`: salvage may remove `.tmp` to + * preserve liveness after an unrecoverable window, but the loss must remain + * visible to a later uploader/agent and session-complete gate. + */ +std::size_t transportLossMarkerCount( + const std::filesystem::path& session_dir); + /** * Return the next append-style window index for `channel` in a session. * Both published root files and unpublished `.tmp` staging files count, so @@ -19,10 +77,16 @@ struct LogSalvageResult { std::size_t nextLogWindowIndex(const std::filesystem::path& session_dir, const std::string& channel); -/** Remove oldest published windows once more than `max_files` exist. */ -void pruneLogWindows(const std::filesystem::path& session_dir, - const std::string& channel, - std::size_t max_files); +/** + * Remove oldest published windows once more than `max_files` exist, and + * return how many were deleted. A nonzero return is DATA LOSS for any + * window the agent had not uploaded yet - callers surface it loudly + * (short rotation cadences reach the cap in minutes: 100 files at a 10 s + * cadence is ~17 min of agent/backend outage tolerance). + */ +std::size_t pruneLogWindows(const std::filesystem::path& session_dir, + const std::string& channel, + std::size_t max_files); /** Publish staged `.tmp/*.log.gz` files and export non-empty `.tmp/*.log`. */ LogSalvageResult salvageSessionTempDir( diff --git a/include/gpufl/core/logger/log_sink.hpp b/include/gpufl/core/logger/log_sink.hpp index e50dd03..b991e4f 100644 --- a/include/gpufl/core/logger/log_sink.hpp +++ b/include/gpufl/core/logger/log_sink.hpp @@ -48,6 +48,15 @@ class ILogSink { * Must not throw. */ virtual void close() = 0; + + /** + * Periodic service beat: publish any transport window whose deadline + * has passed even though no new write arrived (a channel that wrote + * once and went quiet would otherwise hold its window open until the + * next write or shutdown). Called from the collector's flush beat. + * Default: no-op - only sinks with time-windowed output care. + */ + virtual void rotateDueWindows() {} }; } // namespace gpufl diff --git a/include/gpufl/core/logger/logger.cpp b/include/gpufl/core/logger/logger.cpp index c16a278..50f7eb0 100644 --- a/include/gpufl/core/logger/logger.cpp +++ b/include/gpufl/core/logger/logger.cpp @@ -48,6 +48,13 @@ void Logger::addSink(std::unique_ptr sink) { sinks_.push_back(std::move(sink)); } +void Logger::rotateDueWindows() { + std::lock_guard lk(sinks_mu_); + for (auto& sink : sinks_) { + if (sink) sink->rotateDueWindows(); + } +} + void Logger::write(const IJsonSerializable& model) { const std::string json = model.buildJson(); const Channel ch = model.channel(); diff --git a/include/gpufl/core/logger/logger.hpp b/include/gpufl/core/logger/logger.hpp index acc9bba..dd9d147 100644 --- a/include/gpufl/core/logger/logger.hpp +++ b/include/gpufl/core/logger/logger.hpp @@ -1,6 +1,8 @@ #pragma once #include +#include +#include #include #include #include @@ -65,6 +67,37 @@ class Logger { * backend's decompressed body cap - see kDefaultRotateBytes. */ std::size_t rotate_bytes = kDefaultRotateBytes; + /** + * Also rotate once the data in the current window spans more + * than this many milliseconds, measured on the MONOTONIC clock + * from the window's first write. 0 disables the time trigger + * (default). An EMPTY window is never rotated, so idle channels + * produce no empty files. + * + * Two paths reach the deadline: the check before each write + * (immediate on busy channels) and the collector's periodic + * rotateDueWindows() beat, which is what publishes a window + * whose channel has gone quiet. Worst-case publish latency is + * therefore roughly rotate_after_ms + one beat interval + * (~250 ms) + the cutover rename; compression and the publish + * retry happen afterwards on the retirement worker, so they add + * to the window's arrival time but never to the caller's. + */ + std::int64_t rotate_after_ms = 0; + /** + * Monotonic now() in milliseconds, injectable so unit tests + * drive rotation with a fake clock instead of sleeps. Unset + * (default) → std::chrono::steady_clock. Never wall clock: + * NTP/DST jumps must not fire or starve rotation windows. + */ + std::function now_ms; + /** + * Test-only synchronization hook invoked by the retirement worker + * immediately before it starts a slow export. Production leaves this + * empty. It lets concurrency tests block gzip deterministically and + * prove the cutover caller has already returned. + */ + std::function before_retired_export; std::size_t max_files = 100; bool compress_rotated = true; bool flush_always = false; @@ -100,6 +133,12 @@ class Logger { */ void write(const IJsonSerializable& model); + /** + * Forward the collector's periodic beat to every sink so overdue + * transport windows publish without waiting for the next write. + */ + void rotateDueWindows(); + private: Options opt_; std::vector> sinks_; diff --git a/include/gpufl/core/monitor.cpp b/include/gpufl/core/monitor.cpp index 92317ed..74b6aa2 100644 --- a/include/gpufl/core/monitor.cpp +++ b/include/gpufl/core/monitor.cpp @@ -479,6 +479,12 @@ void CollectorLoop() { drainSyntheticKernels(rt, detail::GetTimestampNs() - kMidRunSyntheticGraceNs); } g_state.batches.flushAll(); + // AFTER the batch flush, so this beat's data lands in the + // window being closed. This is the deadline path for the + // time trigger: without it a channel that wrote once and + // went quiet keeps its window in `.tmp` until the next + // write or shutdown. + rt->logger->rotateDueWindows(); } if (g_state.adapter) g_state.adapter->drainProfilingData(); lastFlush = std::chrono::steady_clock::now(); diff --git a/include/gpufl/upload/upload_logs.cpp b/include/gpufl/upload/upload_logs.cpp index eac0963..a401446 100644 --- a/include/gpufl/upload/upload_logs.cpp +++ b/include/gpufl/upload/upload_logs.cpp @@ -49,6 +49,7 @@ #include "gpufl/core/debug_logger.hpp" #include "gpufl/core/host_info.hpp" #include "gpufl/core/json/json.hpp" +#include "gpufl/core/logger/file_compressor.hpp" #include "gpufl/core/logger/log_salvage.hpp" #include "gpufl/core/logger/logger.hpp" #include "gpufl/core/version.hpp" @@ -199,12 +200,26 @@ RepairResult repairOrphanLogIfNeeded(const fs::path& log_path) { if (!fs::exists(log_path, ec)) return {RepairResult::Keep, log_path}; const fs::path gz_path = fs::path(log_path.string() + ".gz"); if (fs::exists(gz_path, ec)) { - // Both files exist - .log is the stale duplicate from a - // failed compress-on-shutdown. Remove it and skip; the .gz - // entry will be added by the iterator's other pass. + // Both files exist. The `.gz` is only the authoritative copy if it + // actually decodes: a compress that died midway, or a rename that + // reached the disk before its data, leaves a truncated or empty + // `.gz` whose mere EXISTENCE used to be enough to delete the raw - + // destroying the only complete copy of the window. + if (gpufl::isValidGzipFile(gz_path)) { + std::error_code rm_ec; + fs::remove(log_path, rm_ec); + return {RepairResult::Skip, log_path}; + } + GFL_LOG_ERROR("[Upload] '", gz_path.string(), + "' is not a readable gzip; rebuilding it from the raw " + "window '", log_path.string(), "'."); std::error_code rm_ec; - fs::remove(log_path, rm_ec); - return {RepairResult::Skip, log_path}; + fs::remove(gz_path, rm_ec); + if (fs::exists(gz_path, rm_ec)) { + // Cannot replace it and cannot trust it - keep both rather than + // choose one, and let the operator see the raw file. + return {RepairResult::Keep, log_path}; + } } // Empty file → just remove. No data to preserve. @@ -213,36 +228,19 @@ RepairResult repairOrphanLogIfNeeded(const fs::path& log_path) { return {RepairResult::Skip, log_path}; } - // Inline gzip using zlib. Read source, compress, write dest, then - // remove source on success. - std::ifstream in(log_path, std::ios::binary); - if (!in) return {RepairResult::Keep, log_path}; - gzFile out = gzopen(gz_path.string().c_str(), "wb"); - if (!out) return {RepairResult::Keep, log_path}; - char buf[64 * 1024]; - bool ok = true; - while (in) { - in.read(buf, sizeof(buf)); - const auto n = in.gcount(); - if (n > 0) { - if (gzwrite(out, buf, static_cast(n)) != static_cast(n)) { - ok = false; - break; - } - } - } - gzclose(out); - in.close(); - if (!ok) { - fs::remove(gz_path, ec); + // Use the shared compressor contract. The old inline copy ignored input + // read errors and gzclose(), wrote under the completed name, and deleted + // the raw even when finalization failed. + GzipFileCompressor compressor; + if (!compressor.compress(log_path.string())) { return {RepairResult::Keep, log_path}; } - fs::remove(log_path, ec); return {RepairResult::Keep, gz_path}; } std::vector discoverFiles(const PathParts& parts) { std::vector out; + std::unordered_set discovered_paths; std::error_code ec; if (!fs::exists(parts.directory, ec) || !fs::is_directory(parts.directory, ec)) { return out; @@ -288,6 +286,12 @@ std::vector discoverFiles(const PathParts& parts) { } df.path = final_path; df.session_id = sid; + // A raw entry repaired into `.gz` can be followed by that newly + // created gzip in the same directory iterator. Treat the path as + // one transport window, not two upload jobs. + const std::string path_key = + final_path.lexically_normal().generic_string(); + if (!discovered_paths.insert(path_key).second) continue; out.push_back(std::move(df)); } } @@ -1037,6 +1041,7 @@ std::vector discoverSessions(const std::vector& fil UploadResult uploadLogs(const UploadOptions& opts) { UploadResult result; + bool transport_loss_detected = false; const auto upload_start = std::chrono::steady_clock::now(); auto elapsedMs = [&]() -> long long { return std::chrono::duration_cast( @@ -1127,23 +1132,38 @@ UploadResult uploadLogs(const UploadOptions& opts) { GFL_LOG_DEBUG("[uploadLogs] salvaged ", salvaged.salvaged, " temp log file(s), deferred ", salvaged.deferred); } + const auto reportTransportLoss = [&](const std::size_t lost_windows) { + if (lost_windows == 0) return; + transport_loss_detected = true; + result.warnings.emplace_back( + "uploadLogs: " + std::to_string(lost_windows) + + " transport window(s) were unrecoverable and discarded before " + "upload; the selected session data is incomplete."); + GFL_LOG_ERROR("[uploadLogs] ", lost_windows, + " unrecoverable window(s) discarded - uploaded data is " + "incomplete."); + }; auto files = discoverFiles(parts); if (files.empty()) { + reportTransportLoss( + static_cast(salvaged.lost_windows)); GFL_LOG_DEBUG("[uploadLogs] no session subdirs found in ", parts.directory.string()); - result.success = true; + result.success = !transport_loss_detected; result.elapsed_ms = elapsedMs(); return result; } const auto all_sessions = discoverSessions(files); if (all_sessions.empty()) { + reportTransportLoss( + static_cast(salvaged.lost_windows)); result.warnings.emplace_back( "uploadLogs: no job_start events found in " + parts.directory.string() + " - the directory has files matching the prefix but none carry " "a session header. Was the session aborted before init?"); - result.success = true; // nothing to upload → not a failure, just a no-op + result.success = !transport_loss_detected; result.elapsed_ms = elapsedMs(); return result; } @@ -1197,7 +1217,7 @@ UploadResult uploadLogs(const UploadOptions& opts) { if (targets.empty()) { // Every session in the dir is already in the cursor. // No work to do - that's a success, not a failure. - result.success = true; + result.success = !transport_loss_detected; result.elapsed_ms = elapsedMs(); GFL_LOG_DEBUG("[uploadLogs] all sessions already in cursor - no-op."); return result; @@ -1224,6 +1244,18 @@ UploadResult uploadLogs(const UploadOptions& opts) { } // ── HTTP client setup ──────────────────────────────────────────── + // Salvage scans every session under the spool root, but a default upload + // targets only the newest session. Do not let an unrelated old session's + // durable loss marker fail a healthy selected upload. Conversely, count + // markers after cursor filtering so already-completed sessions skipped by + // --all-sessions do not become incomplete retroactively. + std::size_t selected_lost_windows = 0; + for (const auto& target : targets) { + selected_lost_windows += + transportLossMarkerCount(parts.directory / target.session_id); + } + reportTransportLoss(selected_lost_windows); + UrlParts url; if (!parseUrl(opts.backend_url, url)) { result.warnings.emplace_back( @@ -1538,7 +1570,10 @@ UploadResult uploadLogs(const UploadOptions& opts) { // file shipped (a skipped file is a hole - leave the session // incomplete so a re-run retries it). Persisted after each // session so a mid-run crash keeps the finished ones skipped. - if (session_ok && posted_anything && !session_had_skips) { + const bool session_has_transport_loss = + transportLossMarkerCount(parts.directory / current_sid) > 0; + if (session_ok && posted_anything && !session_had_skips && + !session_has_transport_loss) { CompletedSession cs; cs.completed_at_iso8601 = nowIso8601Utc(); cs.events = events_from_session; @@ -1563,7 +1598,8 @@ UploadResult uploadLogs(const UploadOptions& opts) { // wasn't an ancient pre-v1.2 one missing the /stream endpoint. The // 404 case has already pushed a clear migration-hint warning into // result.warnings via flushChunk's OldBackend404 branch. - result.success = !auth_failed && !budget_aborted && !old_backend_404; + result.success = !auth_failed && !budget_aborted && !old_backend_404 && + !transport_loss_detected; result.elapsed_ms = elapsedMs(); maybeLogProgress(/*force=*/true); diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index 7ca2d86..fad77a5 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -17,6 +17,7 @@ set(GPUFL_TEST_SOURCES core/test_bench_invoker.cpp core/test_deep_window.cpp core/test_disabled.cpp + core/test_file_log_sink_rotation.cpp core/test_wire_contract.cpp core/test_counter_registry.cpp core/test_nvtx_counters.cpp diff --git a/tests/core/test_file_log_sink_rotation.cpp b/tests/core/test_file_log_sink_rotation.cpp new file mode 100644 index 0000000..bed65c3 --- /dev/null +++ b/tests/core/test_file_log_sink_rotation.cpp @@ -0,0 +1,839 @@ +// Time-based transport-window rotation (rotate_after_ms), driven by a FAKE +// monotonic clock - no sleeps. Windows are observed where consumers observe +// them: published `..log.gz` files in the session dir, plus +// FileLogSink::rotationStats() for WHICH trigger fired (files alone cannot +// say size-vs-time). Contract under test: +// - a window rotates when the data in it spans >= rotate_after_ms +// - an EMPTY window never rotates (idle channels publish no empty files) +// - the window's age starts at its FIRST write, not at channel open +// - when time and size are due at once, time is recorded (it was due +// before this write's bytes existed) +// - a clock that never advances never time-rotates +#include + +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +#include "gpufl/core/logger/file_compressor.hpp" +#include "gpufl/core/logger/file_log_sink.hpp" +#include "gpufl/core/logger/log_rotator.hpp" +#include "gpufl/core/logger/log_salvage.hpp" +#include "gpufl/core/logger/log_sink.hpp" +#include "gpufl/core/logger/logger.hpp" + +namespace fs = std::filesystem; + +namespace { + +bool endsWithSuffix(const std::string& value, const std::string& suffix) { + return value.size() >= suffix.size() && + value.compare(value.size() - suffix.size(), suffix.size(), + suffix) == 0; +} + +// Records the paths the rotator asks the compressor to write, and can be made +// to fail, so the export TRANSACTION can be pinned without needing a crash: +// production's GzipFileCompressor gives no way to observe which name a +// half-written gzip would have had. +class RecordingCompressor final : public gpufl::IFileCompressor { + public: + bool compress(const std::string& path) override { + compress_calls.push_back(path); + return succeed; + } + + bool compressTo(const std::string& src, const std::string& dst) override { + targets.push_back(dst); + // A real compressor leaves bytes behind when it dies mid-write, so + // write first and only then report the failure. + std::ofstream out(dst, std::ios::binary | std::ios::trunc); + out << (succeed ? "pretend-gzip-of:" : "half-written-gzip-of:") << src; + out.close(); + return succeed; + } + + std::vector targets; + std::vector compress_calls; + bool succeed = true; +}; + +class FileLogSinkRotationTest : public ::testing::Test { + protected: + void SetUp() override { + const auto* info = + ::testing::UnitTest::GetInstance()->current_test_info(); + base_ = fs::temp_directory_path() / + (std::string("gpufl_rotation_test_") + info->name()); + fs::remove_all(base_); + fs::create_directories(base_); + } + + void TearDown() override { + std::error_code ec; + fs::remove_all(base_, ec); + } + + gpufl::Logger::Options options(std::int64_t rotate_after_ms, + std::size_t rotate_bytes = 0, + std::size_t max_files = 100) { + gpufl::Logger::Options o; + o.base_path = base_.string(); + o.session_id = "s1"; + o.rotate_bytes = rotate_bytes; // 0 = size trigger off + o.rotate_after_ms = rotate_after_ms; + o.max_files = max_files; + o.now_ms = [this] { return fake_now_ms_; }; + return o; + } + + fs::path sessionDir() const { return base_ / "s1"; } + fs::path tmpDir() const { return sessionDir() / ".tmp"; } + + static void writeText(const fs::path& path, const std::string& text) { + fs::create_directories(path.parent_path()); + std::ofstream out(path, std::ios::binary | std::ios::trunc); + ASSERT_TRUE(out.good()); + out << text; + out.close(); + } + + static void writeEmptyFile(const fs::path& path) { + fs::create_directories(path.parent_path()); + std::ofstream out(path, std::ios::binary | std::ios::trunc); + out.close(); + } + + // Decompresses a published window so a test can assert the EVENTS + // survived, not merely that some file exists at the expected name. + static std::string gunzipToString(const fs::path& path) { + gzFile file = gzopen(path.string().c_str(), "rb"); + if (!file) return {}; + std::string out; + char buffer[8192]; + int read = 0; + while ((read = gzread(file, buffer, sizeof(buffer))) > 0) { + out.append(buffer, static_cast(read)); + } + gzclose(file); + return out; + } + + gpufl::LogRotationOptions rotatorOptions() const { + gpufl::LogRotationOptions r{}; + r.base_path = base_.string(); + r.session_id = "s1"; + r.channel_name = "device"; + r.max_files = 100; + r.compress_rotated = true; + return r; + } + + // Published windows for a channel = `..log.gz` files in the + // session ROOT. The active file lives in `.tmp/` and never counts. + std::size_t publishedWindows(const std::string& channel) const { + const fs::path session_dir = base_ / "s1"; + if (!fs::exists(session_dir)) return 0; + std::size_t n = 0; + for (const auto& e : fs::directory_iterator(session_dir)) { + if (!e.is_regular_file()) continue; + const std::string name = e.path().filename().string(); + if (name.rfind(channel + ".", 0) == 0 && + name.size() >= 7 && + name.compare(name.size() - 7, 7, ".log.gz") == 0) { + ++n; + } + } + return n; + } + + fs::path base_; + std::int64_t fake_now_ms_ = 0; +}; + +TEST_F(FileLogSinkRotationTest, TimeTriggerPublishesOnceWindowSpanExceeded) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + + fake_now_ms_ = 0; + sink.write(gpufl::Channel::Device, R"({"a":1})"); // window 1 starts + fake_now_ms_ = 4999; + sink.write(gpufl::Channel::Device, R"({"a":2})"); // span 4999 < 5000 + EXPECT_EQ(publishedWindows("device"), 0u); + EXPECT_EQ(sink.rotationStats().by_time, 0u); + + fake_now_ms_ = 5000; // span reaches the threshold BEFORE this write + sink.write(gpufl::Channel::Device, R"({"a":3})"); // rotates, then writes + sink.waitForPendingExports(); + EXPECT_EQ(publishedWindows("device"), 1u); + EXPECT_EQ(sink.rotationStats().by_time, 1u); + EXPECT_EQ(sink.rotationStats().by_size, 0u); + + // The new window's age starts at ITS first write (5000), not at the + // rotation or at channel open - no instant re-rotation. + fake_now_ms_ = 9999; + sink.write(gpufl::Channel::Device, R"({"a":4})"); + EXPECT_EQ(sink.rotationStats().by_time, 1u); + fake_now_ms_ = 10000; + sink.write(gpufl::Channel::Device, R"({"a":5})"); + sink.waitForPendingExports(); + EXPECT_EQ(sink.rotationStats().by_time, 2u); + EXPECT_EQ(publishedWindows("device"), 2u); + EXPECT_EQ(sink.rotationStats().published, 2u); +} + +TEST_F(FileLogSinkRotationTest, EmptyWindowNeverRotatesNoMatterHowLate) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + + // Channel idle far past the threshold: the first write must NOT rotate + // (an empty window has no age) - it starts window 1 instead. + fake_now_ms_ = 100000; + sink.write(gpufl::Channel::Device, R"({"first":true})"); + EXPECT_EQ(publishedWindows("device"), 0u); + EXPECT_EQ(sink.rotationStats().by_time, 0u); +} + +TEST_F(FileLogSinkRotationTest, SizeTriggerStillRotatesAndRecordsSize) { + // Time trigger OFF; size threshold small enough that the second line + // would push past it. + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/0, + /*rotate_bytes=*/64)); + + const std::string line(40, 'x'); + sink.write(gpufl::Channel::Device, line); // 41 bytes + EXPECT_EQ(publishedWindows("device"), 0u); + sink.write(gpufl::Channel::Device, line); // 82 > 64 → rotate + sink.waitForPendingExports(); + EXPECT_EQ(publishedWindows("device"), 1u); + EXPECT_EQ(sink.rotationStats().by_size, 1u); + EXPECT_EQ(sink.rotationStats().by_time, 0u); +} + +TEST_F(FileLogSinkRotationTest, TimeRecordedWhenBothTriggersDue) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000, + /*rotate_bytes=*/64)); + + const std::string line(40, 'x'); + fake_now_ms_ = 0; + sink.write(gpufl::Channel::Device, line); + fake_now_ms_ = 6000; // time overdue AND next write exceeds 64 bytes + sink.write(gpufl::Channel::Device, line); + sink.waitForPendingExports(); + EXPECT_EQ(publishedWindows("device"), 1u); + EXPECT_EQ(sink.rotationStats().by_time, 1u); + EXPECT_EQ(sink.rotationStats().by_size, 0u); +} + +TEST_F(FileLogSinkRotationTest, FrozenClockNeverTimeRotates) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + + fake_now_ms_ = 42; // never advances + for (int i = 0; i < 100; ++i) { + sink.write(gpufl::Channel::Device, R"({"i":1})"); + } + EXPECT_EQ(publishedWindows("device"), 0u); + EXPECT_EQ(sink.rotationStats().by_time, 0u); + EXPECT_EQ(sink.rotationStats().by_size, 0u); +} + +TEST_F(FileLogSinkRotationTest, CloseWithoutWritesPublishesNothing) { + { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + fake_now_ms_ = 100000; // channels stay empty the whole time + } // destructor closes + EXPECT_EQ(publishedWindows("device"), 0u); + EXPECT_EQ(publishedWindows("scope"), 0u); + EXPECT_EQ(publishedWindows("system"), 0u); + EXPECT_EQ(publishedWindows("sass"), 0u); +} + +TEST_F(FileLogSinkRotationTest, CloseExportsTheFinalNonEmptyWindow) { + { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + sink.write(gpufl::Channel::Device, R"({"tail":true})"); + } // close exports the active window + EXPECT_EQ(publishedWindows("device"), 1u); +} + +// THE deadline case: a channel writes once and goes quiet. The write-path +// trigger alone would hold that window in `.tmp` until the next write or +// shutdown - rotateDueWindows() (the collector beat) must publish it. +TEST_F(FileLogSinkRotationTest, DeadlineRotationPublishesWithoutFurtherWrites) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + + fake_now_ms_ = 0; + sink.write(gpufl::Channel::Device, R"({"only":true})"); + fake_now_ms_ = 10000; + sink.rotateDueWindows(); + sink.waitForPendingExports(); // no write in between + EXPECT_EQ(publishedWindows("device"), 1u); + EXPECT_EQ(sink.rotationStats().by_time, 1u); + + // The fresh window is empty - servicing again must not publish an + // empty file or count another rotation. + fake_now_ms_ = 100000; + sink.rotateDueWindows(); + sink.waitForPendingExports(); + EXPECT_EQ(publishedWindows("device"), 1u); + EXPECT_EQ(sink.rotationStats().by_time, 1u); +} + +TEST_F(FileLogSinkRotationTest, RotateDueWindowsSkipsEmptyAndFreshWindows) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + + // Nothing ever written anywhere: the beat is a global no-op. + fake_now_ms_ = 50000; + sink.rotateDueWindows(); + sink.waitForPendingExports(); + EXPECT_EQ(sink.rotationStats().by_time, 0u); + + // A fresh window (age < deadline) is left alone. + sink.write(gpufl::Channel::Device, R"({"fresh":true})"); + fake_now_ms_ = 54999; + sink.rotateDueWindows(); + sink.waitForPendingExports(); + EXPECT_EQ(publishedWindows("device"), 0u); + EXPECT_EQ(sink.rotationStats().by_time, 0u); +} + +// Cutover blocked (the retire rename is denied) must NOT count as a +// rotation and must NOT reset the window age - the very next beat retries +// instead of waiting out a fresh rotate_after_ms. +TEST_F(FileLogSinkRotationTest, BlockedCutoverKeepsWindowAgeAndRetries) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + + // Sabotage: a DIRECTORY at the retire target `.tmp/device.1.log` + // makes the cutover rename fail. Index scans skip non-regular files, + // so the name still resolves to index 1. + fs::create_directories(tmpDir() / "device.1.log"); + + fake_now_ms_ = 0; + sink.write(gpufl::Channel::Device, R"({"blocked":true})"); + fake_now_ms_ = 6000; + sink.rotateDueWindows(); + sink.waitForPendingExports(); + EXPECT_EQ(publishedWindows("device"), 0u); + EXPECT_EQ(sink.rotationStats().cutover_blocked, 1u); + EXPECT_EQ(sink.rotationStats().by_time, 0u); + + // Clear the blockage; retry WITHOUT advancing the clock. Only a + // preserved window age lets this rotate immediately. + fs::remove(tmpDir() / "device.1.log"); + sink.rotateDueWindows(); + sink.waitForPendingExports(); + EXPECT_EQ(publishedWindows("device"), 1u); + EXPECT_EQ(sink.rotationStats().by_time, 1u); + EXPECT_EQ(sink.rotationStats().cutover_blocked, 1u); +} + +// Publish blocked AFTER the window was cut over: it sits in `.tmp` +// staging for the salvage pass. The CUTOVER still counts (the boundary +// really happened and the data is immutable); the export counts staged, +// never published. +TEST_F(FileLogSinkRotationTest, StagedPublishCountsStagedNotPublished) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + + // A DIRECTORY at the publish target blocks the final rename only. + fs::create_directories(sessionDir() / "device.1.log.gz"); + + fake_now_ms_ = 0; + sink.write(gpufl::Channel::Device, R"({"staged":true})"); + fake_now_ms_ = 6000; + sink.rotateDueWindows(); + sink.waitForPendingExports(); // ~700ms of backoff, on the worker + EXPECT_EQ(publishedWindows("device"), 0u); + EXPECT_EQ(sink.rotationStats().by_time, 1u); // cutover happened + EXPECT_EQ(sink.rotationStats().staged, 1u); + EXPECT_EQ(sink.rotationStats().published, 0u); + EXPECT_TRUE(fs::is_regular_file(tmpDir() / "device.1.log.gz")); + + // The active window restarted: the next window publishes as index 2 + // (staging keeps index 1 reserved - no overwrite). + sink.write(gpufl::Channel::Device, R"({"next":true})"); + fake_now_ms_ = 12000; + sink.rotateDueWindows(); + sink.waitForPendingExports(); + EXPECT_TRUE(fs::is_regular_file(sessionDir() / "device.2.log.gz")); + EXPECT_EQ(sink.rotationStats().published, 1u); +} + +// The whole point of the split: the thread that hits the boundary does a +// rename and nothing else. Compression and the publish backoff must NOT +// have run when rotateDueWindows() returns - otherwise the collector beat +// pays for gzip and stops draining the CUPTI ring. +TEST_F(FileLogSinkRotationTest, CutoverReturnsWhileWorkerExportIsBlocked) { + std::promise worker_entered_promise; + auto worker_entered = worker_entered_promise.get_future(); + std::promise release_worker_promise; + const auto release_worker = release_worker_promise.get_future().share(); + bool entered = false; + + auto opt = options(/*rotate_after_ms=*/5000); + opt.before_retired_export = [&] { + if (!entered) { + entered = true; + worker_entered_promise.set_value(); + } + release_worker.wait(); + }; + gpufl::FileLogSink sink(opt); + + fake_now_ms_ = 0; + sink.write(gpufl::Channel::Device, R"({"a":1})"); + fake_now_ms_ = 6000; + + // Run the cutover on a future so the same test also catches a mutation + // that performs export inline: the worker hook is reached, but the + // cutover future cannot become ready until the hook is released. + auto cutover = std::async(std::launch::async, + [&] { sink.rotateDueWindows(); }); + const auto entered_status = + worker_entered.wait_for(std::chrono::seconds(2)); + if (entered_status != std::future_status::ready) { + // Never strand the async future behind the test latch on a failure. + release_worker_promise.set_value(); + cutover.wait(); + FAIL() << "retirement worker did not reach the export hook"; + return; + } + EXPECT_EQ(cutover.wait_for(std::chrono::milliseconds(500)), + std::future_status::ready); + + // The worker is still blocked, but the immutable raw file exists and + // the active channel accepts the next window. + EXPECT_TRUE(fs::is_regular_file(tmpDir() / "device.1.log")); + sink.write(gpufl::Channel::Device, R"({"next":true})"); + fake_now_ms_ = 12000; + sink.rotateDueWindows(); // queue a second window behind the blocked one + EXPECT_EQ(sink.rotationStats().by_time, 2u); + EXPECT_EQ(sink.rotationStats().pending_exports, 2u); + + release_worker_promise.set_value(); + cutover.get(); + sink.waitForPendingExports(); + EXPECT_EQ(sink.rotationStats().published, 2u); + EXPECT_EQ(sink.rotationStats().pending_exports, 0u); + EXPECT_GE(sink.rotationStats().max_pending_exports, 2u); + EXPECT_GT(sink.rotationStats().max_pending_export_bytes, 0u); +} + +TEST_F(FileLogSinkRotationTest, + SalvageDropsPartialGzipAndPublishesRawExactlyOnce) { + fs::create_directories(tmpDir()); + writeText(tmpDir() / "device.1.log", R"({"window":1})"); + writeText(tmpDir() / "device.1.log.gz.part", "incomplete gzip bytes"); + + const auto result = gpufl::salvageSessionTempDir(sessionDir()); + + EXPECT_EQ(result.deferred, 0u); + EXPECT_EQ(publishedWindows("device"), 1u); + EXPECT_TRUE(fs::is_regular_file(sessionDir() / "device.1.log.gz")); + EXPECT_FALSE(fs::exists(sessionDir() / "device.2.log.gz")); + EXPECT_FALSE(fs::exists(tmpDir())); +} + +TEST_F(FileLogSinkRotationTest, + SalvagePrefersCompletedGzipOverDuplicateRaw) { + fs::create_directories(tmpDir()); + const fs::path raw = tmpDir() / "device.1.log"; + const fs::path gzip = tmpDir() / "device.1.log.gz"; + writeText(raw, R"({"window":1})"); + gpufl::GzipFileCompressor compressor; + ASSERT_TRUE(compressor.compressTo(raw.string(), gzip.string())); + + const auto result = gpufl::salvageSessionTempDir(sessionDir()); + + EXPECT_EQ(result.deferred, 0u); + EXPECT_EQ(publishedWindows("device"), 1u); + EXPECT_TRUE(fs::is_regular_file(sessionDir() / "device.1.log.gz")); + EXPECT_FALSE(fs::exists(sessionDir() / "device.2.log.gz")); + EXPECT_FALSE(fs::exists(tmpDir())); +} + +TEST_F(FileLogSinkRotationTest, + SalvageRejectsCorruptGzipAndRecoversCompleteRaw) { + fs::create_directories(tmpDir()); + const fs::path raw = tmpDir() / "device.1.log"; + const fs::path gzip = tmpDir() / "device.1.log.gz"; + writeText(raw, R"({"window":1,"payload":"enough bytes for a gzip"})"); + gpufl::GzipFileCompressor compressor; + ASSERT_TRUE(compressor.compressTo(raw.string(), gzip.string())); + const auto complete_size = fs::file_size(gzip); + ASSERT_GT(complete_size, 8u); + fs::resize_file(gzip, complete_size - 8); // crash before gzip trailer + + const auto result = gpufl::salvageSessionTempDir(sessionDir()); + + EXPECT_EQ(result.deferred, 0u); + EXPECT_EQ(publishedWindows("device"), 1u); + EXPECT_TRUE(fs::is_regular_file(sessionDir() / "device.1.log.gz")); + EXPECT_FALSE(fs::exists(sessionDir() / "device.2.log.gz")); + EXPECT_FALSE(fs::exists(tmpDir())); +} + +TEST_F(FileLogSinkRotationTest, + SalvageDoesNotRepublishRawWhenSameIndexAlreadyPublished) { + fs::create_directories(tmpDir()); + const fs::path raw = tmpDir() / "device.1.log"; + writeText(raw, R"({"window":1})"); + gpufl::GzipFileCompressor compressor; + ASSERT_TRUE(compressor.compressTo( + raw.string(), (sessionDir() / "device.1.log.gz").string())); + + const auto result = gpufl::salvageSessionTempDir(sessionDir()); + + EXPECT_EQ(result.deferred, 0u); + EXPECT_EQ(publishedWindows("device"), 1u); + EXPECT_FALSE(fs::exists(sessionDir() / "device.2.log.gz")); + EXPECT_FALSE(fs::exists(tmpDir())); +} + +// zlib reports EOF-on-first-read as a CLEAN read, so a zero-length file used +// to validate as a gzip. A rename publishes a directory entry before the data +// is necessarily durable, so a power loss right after `.part` -> `.gz` can +// leave an empty `.gz` beside its still-complete raw source. Validating it +// deleted the raw as a duplicate and published the empty file as the window: +// a full window lost, silently, with `.tmp` swept clean afterwards. +TEST_F(FileLogSinkRotationTest, SalvageRefusesEmptyGzipAndRecoversTheRaw) { + fs::create_directories(tmpDir()); + const std::string payload = R"({"window":1,"payload":"must survive"})"; + writeText(tmpDir() / "device.1.log", payload); + writeEmptyFile(tmpDir() / "device.1.log.gz"); + ASSERT_EQ(fs::file_size(tmpDir() / "device.1.log.gz"), 0u); + + const auto result = gpufl::salvageSessionTempDir(sessionDir()); + + EXPECT_EQ(result.deferred, 0u); + EXPECT_EQ(publishedWindows("device"), 1u); + // The events themselves must be what got published - not the empty file. + EXPECT_EQ(gunzipToString(sessionDir() / "device.1.log.gz"), payload); + EXPECT_FALSE(fs::exists(sessionDir() / "device.2.log.gz")); + EXPECT_FALSE(fs::exists(tmpDir())); +} + +// Same crash window, one step later: the raw was already removed when the +// power went. The events are genuinely gone, but the empty artifact must not +// pin `.tmp` - that directory is the "session still writing" signal, so a +// permanently deferred zero-byte file would leave the session looking +// unfinished to the uploader and the agent forever. +TEST_F(FileLogSinkRotationTest, SalvageDiscardsEmptyGzipWithNoSource) { + fs::create_directories(tmpDir()); + writeEmptyFile(tmpDir() / "device.1.log.gz"); + + const auto result = gpufl::salvageSessionTempDir(sessionDir()); + + EXPECT_EQ(result.deferred, 0u); + EXPECT_EQ(publishedWindows("device"), 0u); + EXPECT_FALSE(fs::exists(tmpDir())); + // Terminal, and it must be COUNTED: once the artifact is gone the + // session looks clean everywhere downstream, so this number is the only + // thing that can tell anyone the upload has a hole in it. + EXPECT_EQ(result.lost_windows, 1); +} + +// The same loss, reported through the sink that owns the session, because +// FileLogSink::close() is where an in-process run learns about it. +TEST_F(FileLogSinkRotationTest, CloseReportsUnrecoverableWindowsAsLost) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + sink.write(gpufl::Channel::Device, R"({"live":true})"); + // A window whose bytes never reached the disk, with its raw already + // gone: nothing on disk can still yield those events. + writeEmptyFile(tmpDir() / "device.7.log.gz"); + + sink.close(); + + EXPECT_EQ(sink.rotationStats().lost_windows, 1u); +} + +// Window indices must come from the channel, never from a fresh directory +// scan. nextWindowIndex() scans `.tmp` and the session root, and the export +// worker moves files between exactly those two directories with no lock +// held, so a window in flight can be missed by BOTH scans - the index is +// handed out twice and fs::rename replaces the published window silently. +// Deleting a published window is a deterministic stand-in for that race: +// a filesystem-derived index would drop back to 1 and collide. +TEST_F(FileLogSinkRotationTest, WindowIndicesNeverGoBackwards) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + + fake_now_ms_ = 0; + sink.write(gpufl::Channel::Device, R"({"w":1})"); + fake_now_ms_ = 6000; + sink.rotateDueWindows(); + sink.waitForPendingExports(); + ASSERT_TRUE(fs::exists(sessionDir() / "device.1.log.gz")); + + // The published window leaves the directory (pruned, uploaded and + // swept, or an operator moved it) - the allocator must not care. + fs::remove(sessionDir() / "device.1.log.gz"); + + sink.write(gpufl::Channel::Device, R"({"w":2})"); + fake_now_ms_ = 12000; + sink.rotateDueWindows(); + sink.waitForPendingExports(); + + EXPECT_TRUE(fs::exists(sessionDir() / "device.2.log.gz")); + EXPECT_FALSE(fs::exists(sessionDir() / "device.1.log.gz")); + EXPECT_EQ(sink.rotationStats().published, 2u); +} + +// Shutdown owns the same monotonic index sequence as mid-run rotation. It +// must not re-scan a directory whose acknowledged windows may have gone. +TEST_F(FileLogSinkRotationTest, FinalWindowIndexNeverGoesBackwards) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + + fake_now_ms_ = 0; + sink.write(gpufl::Channel::Device, R"({"w":1})"); + fake_now_ms_ = 6000; + sink.rotateDueWindows(); + sink.waitForPendingExports(); + ASSERT_TRUE(fs::exists(sessionDir() / "device.1.log.gz")); + + fs::remove(sessionDir() / "device.1.log.gz"); + sink.write(gpufl::Channel::Device, R"({"w":2})"); + sink.close(); + + EXPECT_TRUE(fs::exists(sessionDir() / "device.2.log.gz")); + EXPECT_FALSE(fs::exists(sessionDir() / "device.1.log.gz")); +} + +// Defence in depth for the same hazard: even if an index were reused, the +// export must refuse to rename over an existing window rather than destroy +// it. The bytes stay in `.tmp` for salvage to reconcile. +TEST_F(FileLogSinkRotationTest, ExportRefusesToOverwriteAPublishedWindow) { + RecordingCompressor compressor; + gpufl::LogFileRotator rotator(rotatorOptions(), &compressor); + writeText(sessionDir() / "device.1.log.gz", "the already-published window"); + writeText(tmpDir() / "device.1.log", R"({"w":"second"})"); + + std::size_t pruned = 0; + const auto result = rotator.exportRetiredWindow(1, &pruned); + + EXPECT_EQ(result, + gpufl::LogFileRotator::ExportWindowResult::StagedForSalvage); + // The original window is untouched. + EXPECT_EQ(fs::file_size(sessionDir() / "device.1.log.gz"), + std::string("the already-published window").size()); +} + +// Refusing the overwrite is only half the contract: a later salvage pass must +// not call the staged file a retry duplicate merely because the index matches. +TEST_F(FileLogSinkRotationTest, + CollisionSurvivesSalvageWhenPayloadsAreDifferent) { + fs::create_directories(tmpDir()); + const fs::path published_raw = sessionDir() / "published.raw"; + const fs::path staged_raw = tmpDir() / "device.1.log"; + const fs::path published = sessionDir() / "device.1.log.gz"; + writeText(published_raw, R"({"window":"first"})"); + writeText(staged_raw, R"({"window":"second"})"); + + gpufl::GzipFileCompressor compressor; + ASSERT_TRUE( + compressor.compressTo(published_raw.string(), published.string())); + fs::remove(published_raw); + + gpufl::LogFileRotator rotator(rotatorOptions(), &compressor); + std::size_t pruned = 0; + ASSERT_EQ(rotator.exportRetiredWindow(1, &pruned), + gpufl::LogFileRotator::ExportWindowResult::StagedForSalvage); + ASSERT_TRUE(fs::exists(tmpDir() / "device.1.log.gz")); + + const auto salvage = gpufl::salvageSessionTempDir(sessionDir()); + + EXPECT_GT(salvage.deferred, 0); + EXPECT_EQ(gunzipToString(published), R"({"window":"first"})"); + EXPECT_EQ(gunzipToString(tmpDir() / "device.1.log.gz"), + R"({"window":"second"})"); +} + +// And the cutover half: retiring onto an index that already has a retired +// window would clobber a window waiting to be exported. +TEST_F(FileLogSinkRotationTest, CutoverRefusesToOverwriteARetiredWindow) { + RecordingCompressor compressor; + gpufl::LogFileRotator rotator(rotatorOptions(), &compressor); + writeText(tmpDir() / "device.1.log", "a window awaiting export"); + writeText(tmpDir() / "device.log", "the active window"); + + EXPECT_EQ(rotator.retireActiveWindow(1), + gpufl::LogFileRotator::RetireResult::Blocked); + EXPECT_EQ(gunzipToString(tmpDir() / "device.1.log"), + "a window awaiting export"); + EXPECT_TRUE(fs::exists(tmpDir() / "device.log")); +} + +// removeOrTruncateFile deliberately leaves a zero-byte husk when it cannot +// unlink. Treating that husk as "the complete raw source" authorises +// deleting a corrupt-but-partly-readable gzip - the window's last copy. +TEST_F(FileLogSinkRotationTest, SalvagePreservesCorruptGzipWhenRawIsEmpty) { + fs::create_directories(tmpDir()); + const fs::path raw = tmpDir() / "device.1.log"; + const fs::path gzip = tmpDir() / "device.1.log.gz"; + writeText(raw, R"({"window":1,"payload":"enough bytes for a gzip"})"); + gpufl::GzipFileCompressor compressor; + ASSERT_TRUE(compressor.compressTo(raw.string(), gzip.string())); + const auto complete_size = fs::file_size(gzip); + ASSERT_GT(complete_size, 8u); + fs::resize_file(gzip, complete_size - 8); // crash before the trailer + fs::resize_file(raw, 0); // truncate-fallback husk + + const auto result = gpufl::salvageSessionTempDir(sessionDir()); + + // The only remaining bytes must survive for manual recovery, and the + // session must stay visibly unfinished rather than silently complete. + EXPECT_GT(result.deferred, 0); + EXPECT_EQ(result.lost_windows, 0); + EXPECT_TRUE(fs::exists(gzip)); + EXPECT_EQ(fs::file_size(gzip), complete_size - 8); + EXPECT_EQ(publishedWindows("device"), 0u); +} + +TEST_F(FileLogSinkRotationTest, TerminalLossMarkerSurvivesLaterSalvagePasses) { + fs::create_directories(tmpDir()); + writeEmptyFile(tmpDir() / "device.9.log.gz"); + + const auto first = gpufl::salvageSessionTempDir(sessionDir()); + ASSERT_EQ(first.lost_windows, 1); + ASSERT_EQ(gpufl::transportLossMarkerCount(sessionDir()), 1u); + ASSERT_FALSE(fs::exists(tmpDir())); + + const auto later = gpufl::salvageSessionTempDir(sessionDir()); + EXPECT_EQ(later.lost_windows, 1); + EXPECT_EQ(gpufl::transportLossMarkerCount(sessionDir()), 1u); +} + +// The export transaction itself, pinned at the rotator. Compressing straight +// to `.log.gz` would make a half-written file indistinguishable from +// a finished window after a crash, and no higher-level test notices: the +// salvage fixtures construct their `.part` files by hand, so they stay green +// either way. +TEST_F(FileLogSinkRotationTest, ExportOnlyEverCompressesToAPartFile) { + RecordingCompressor compressor; + gpufl::LogFileRotator rotator(rotatorOptions(), &compressor); + writeText(tmpDir() / "device.1.log", R"({"window":1})"); + + std::size_t pruned = 0; + const auto result = rotator.exportRetiredWindow(1, &pruned); + + EXPECT_EQ(result, gpufl::LogFileRotator::ExportWindowResult::Published); + ASSERT_EQ(compressor.targets.size(), 1u); + EXPECT_TRUE(endsWithSuffix(compressor.targets[0], ".log.gz.part")) + << "compressor wrote directly to " << compressor.targets[0]; + EXPECT_TRUE(fs::exists(sessionDir() / "device.1.log.gz")); + EXPECT_FALSE(fs::exists(tmpDir() / "device.1.log")); + EXPECT_FALSE(fs::exists(tmpDir() / "device.1.log.gz.part")); +} + +// A compressor that dies mid-write must leave the raw source authoritative +// and nothing under the completed name - otherwise salvage would trust the +// stump as a finished window. +TEST_F(FileLogSinkRotationTest, FailedCompressionLeavesNoCompletedGzip) { + RecordingCompressor compressor; + compressor.succeed = false; + gpufl::LogFileRotator rotator(rotatorOptions(), &compressor); + const std::string payload = R"({"window":1})"; + writeText(tmpDir() / "device.1.log", payload); + + std::size_t pruned = 0; + const auto result = rotator.exportRetiredWindow(1, &pruned); + + EXPECT_EQ(result, + gpufl::LogFileRotator::ExportWindowResult::DeferredInActive); + EXPECT_TRUE(fs::exists(tmpDir() / "device.1.log")); + EXPECT_FALSE(fs::exists(tmpDir() / "device.1.log.gz")); + EXPECT_FALSE(fs::exists(tmpDir() / "device.1.log.gz.part")); + EXPECT_EQ(publishedWindows("device"), 0u); +} + +// Publishing while the raw source survives is what produces DUPLICATE rows: +// salvage would later hand the leftover raw a fresh index and publish the +// same events a second time. The export must stage instead. +TEST_F(FileLogSinkRotationTest, ExportRefusesToPublishWhileTheRawSurvives) { + RecordingCompressor compressor; + gpufl::LogFileRotator rotator(rotatorOptions(), &compressor); + // A non-empty DIRECTORY at the raw window's path makes both the remove + // and the truncate fallback fail, portably. + fs::create_directories(tmpDir() / "device.1.log" / "holder"); + writeText(tmpDir() / "device.1.log" / "holder" / "pin", "x"); + + std::size_t pruned = 0; + const auto result = rotator.exportRetiredWindow(1, &pruned); + + EXPECT_EQ(result, + gpufl::LogFileRotator::ExportWindowResult::StagedForSalvage); + EXPECT_EQ(publishedWindows("device"), 0u); + EXPECT_TRUE(fs::exists(tmpDir() / "device.1.log.gz")); +} + +// A cut-over window still publishes even if close() arrives while the +// export is queued: close drains the worker before sweeping `.tmp`. +TEST_F(FileLogSinkRotationTest, CloseDrainsPendingExports) { + { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + fake_now_ms_ = 0; + sink.write(gpufl::Channel::Device, R"({"early":true})"); + fake_now_ms_ = 6000; + sink.rotateDueWindows(); // no waitForPendingExports here + sink.write(gpufl::Channel::Device, R"({"late":true})"); + } // close(): drain worker, then export the final active window + EXPECT_EQ(publishedWindows("device"), 2u); + EXPECT_FALSE(fs::exists(tmpDir())); +} + +// The max_files cap deletes the OLDEST published windows regardless of +// whether anything uploaded them - that is potential data loss and must be +// counted, never silent. (10 s cadence at the default cap of 100 is only +// ~17 min of agent outage tolerance.) +TEST_F(FileLogSinkRotationTest, PruneOnPublishIsCountedAsDataLoss) { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000, + /*rotate_bytes=*/0, + /*max_files=*/2)); + + for (int i = 1; i <= 3; ++i) { + sink.write(gpufl::Channel::Device, R"({"w":1})"); + fake_now_ms_ += 5000; + sink.rotateDueWindows(); + sink.waitForPendingExports(); + } + // Three windows published, cap 2: the oldest was pruned. + EXPECT_EQ(publishedWindows("device"), 2u); + EXPECT_EQ(sink.rotationStats().by_time, 3u); + EXPECT_EQ(sink.rotationStats().pruned_windows, 1u); + EXPECT_FALSE(fs::exists(sessionDir() / "device.1.log.gz")); + EXPECT_TRUE(fs::exists(sessionDir() / "device.3.log.gz")); +} + +// Wiring: the collector beat calls Logger::rotateDueWindows(), which must +// reach every sink exactly once. (Monitor's 250 ms beat → Logger is closed +// by the 3090 sparse-channel run.) +TEST(LoggerRotateDueWindowsTest, ForwardsToEverySinkExactlyOnce) { + class CountingSink : public gpufl::ILogSink { + public: + void write(gpufl::Channel, std::string_view) override {} + void close() override {} + void rotateDueWindows() override { ++calls; } + int calls = 0; + }; + + gpufl::Logger logger; + auto first = std::make_unique(); + auto second = std::make_unique(); + CountingSink* first_raw = first.get(); + CountingSink* second_raw = second.get(); + logger.addSink(std::move(first)); + logger.addSink(std::move(second)); + + logger.rotateDueWindows(); + EXPECT_EQ(first_raw->calls, 1); + EXPECT_EQ(second_raw->calls, 1); + + logger.rotateDueWindows(); + EXPECT_EQ(first_raw->calls, 2); + EXPECT_EQ(second_raw->calls, 2); +} + +} // namespace diff --git a/tests/upload/test_upload_logs.cpp b/tests/upload/test_upload_logs.cpp index 1bcb2c5..9f1a23c 100644 --- a/tests/upload/test_upload_logs.cpp +++ b/tests/upload/test_upload_logs.cpp @@ -1025,6 +1025,94 @@ TEST(UploadLogs, SalvagesSessionTmpBeforeDiscovery) { fs::remove_all(tmp); } +TEST(UploadLogs, DurableTransportLossMarkerPreventsSuccessfulCompletion) { + const fs::path tmp = + fs::temp_directory_path() / "gpufl_upload_test_transport_loss"; + fs::remove_all(tmp); + const std::string log_path = makeMinimalSession(tmp, "lost"); + writeLog(tmp / "lost" / ".gpufl-transport-loss.device.3.json", { + R"({"schema_version":1,"type":"transport_window_loss","channel":"device","window_index":3,"reason":"empty_gzip_no_raw"})", + }); + + CaptureServer srv; + gpufl::UploadOptions opts; + opts.log_path = log_path; + opts.backend_url = srv.base_url(); + opts.api_key = "x"; + opts.report_progress = false; + + const auto result = gpufl::uploadLogs(opts); + + EXPECT_FALSE(result.success); + EXPECT_FALSE(result.warnings.empty()); + EXPECT_EQ(srv.snapshot().size(), 3u) + << "healthy windows should still upload even though completion fails"; + EXPECT_TRUE(fs::exists( + tmp / "lost" / ".gpufl-transport-loss.device.3.json")); + + fs::remove_all(tmp); +} + +TEST(UploadLogs, OldSessionLossDoesNotFailTheSelectedLatestSession) { + const fs::path tmp = + fs::temp_directory_path() / "gpufl_upload_test_unrelated_loss"; + fs::remove_all(tmp); + (void)makeMinimalSession(tmp, "old"); + (void)makeMinimalSession(tmp, "z_latest"); + writeLog(tmp / "old" / ".gpufl-transport-loss.device.3.json", { + R"({"schema_version":1,"type":"transport_window_loss","channel":"device","window_index":3,"reason":"empty_gzip_no_raw"})", + }); + + CaptureServer srv; + gpufl::UploadOptions opts; + opts.log_path = tmp.string(); + opts.backend_url = srv.base_url(); + opts.api_key = "x"; + opts.report_progress = false; + + const auto result = gpufl::uploadLogs(opts); + + EXPECT_TRUE(result.success); + EXPECT_TRUE(result.warnings.empty()); + EXPECT_EQ(srv.allEvents().size(), 6u) + << "the default upload should contain only the healthy latest session"; + for (const auto& [type, session_id] : srv.allEvents()) { + (void)type; + EXPECT_EQ(session_id, "z_latest"); + } + + fs::remove_all(tmp); +} + +TEST(UploadLogs, OrphanRawRepairProducesOneValidatedUploadFile) { + const fs::path tmp = + fs::temp_directory_path() / "gpufl_upload_test_orphan_repair"; + fs::remove_all(tmp); + fs::create_directories(tmp / "orphan"); + writeLog(tmp / "orphan" / "device.log", { + R"({"type":"job_start","session_id":"orphan","ts_ns":1})", + R"({"type":"shutdown","session_id":"orphan","ts_ns":2})", + }); + + CaptureServer srv; + gpufl::UploadOptions opts; + opts.log_path = tmp.string(); + opts.backend_url = srv.base_url(); + opts.api_key = "x"; + opts.report_progress = false; + + const auto result = gpufl::uploadLogs(opts); + + EXPECT_TRUE(result.success); + EXPECT_EQ(srv.snapshot().size(), 1u) + << "the repaired path and its directory entry must be deduplicated"; + EXPECT_TRUE(fs::exists(tmp / "orphan" / "device.log.gz")); + EXPECT_FALSE(fs::exists(tmp / "orphan" / "device.log")); + EXPECT_EQ(srv.allEvents().size(), 2u); + + fs::remove_all(tmp); +} + TEST(UploadLogs, ManyEventsShipInOneRequestPerFile) { // U1 regression guard: a file with far more lines than the old // 5000-line chunk cap still ships in exactly ONE request - the From 30133bb657e647ed074de92335d980fd97ea96b6 Mon Sep 17 00:00:00 2001 From: Myoungho Shin Date: Wed, 29 Jul 2026 09:27:55 -0700 Subject: [PATCH 2/5] feat(logger): make transport windows identity-safe --- CMakeLists.txt | 2 + include/gpufl/core/logger/file_log_sink.cpp | 47 +++- include/gpufl/core/logger/file_log_sink.hpp | 11 +- include/gpufl/core/logger/log_rotator.cpp | 45 +++- include/gpufl/core/logger/log_rotator.hpp | 7 +- include/gpufl/core/logger/log_salvage.cpp | 34 ++- include/gpufl/core/logger/log_salvage.hpp | 13 + .../gpufl/core/logger/session_ownership.cpp | 203 +++++++++++++++ .../gpufl/core/logger/session_ownership.hpp | 55 ++++ include/gpufl/core/logger/window_metadata.cpp | 236 ++++++++++++++++++ include/gpufl/core/logger/window_metadata.hpp | 52 ++++ tests/core/test_file_log_sink_rotation.cpp | 166 ++++++++++++ 12 files changed, 852 insertions(+), 19 deletions(-) create mode 100644 include/gpufl/core/logger/session_ownership.cpp create mode 100644 include/gpufl/core/logger/session_ownership.hpp create mode 100644 include/gpufl/core/logger/window_metadata.cpp create mode 100644 include/gpufl/core/logger/window_metadata.hpp diff --git a/CMakeLists.txt b/CMakeLists.txt index cc8226b..c3e9f85 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -155,6 +155,8 @@ target_sources(gpufl PRIVATE include/gpufl/core/logger/logger.cpp include/gpufl/core/logger/log_rotator.cpp include/gpufl/core/logger/log_salvage.cpp + include/gpufl/core/logger/session_ownership.cpp + include/gpufl/core/logger/window_metadata.cpp include/gpufl/core/logger/file_log_sink.cpp include/gpufl/upload/upload_logs.cpp include/gpufl/core/host_info.cpp diff --git a/include/gpufl/core/logger/file_log_sink.cpp b/include/gpufl/core/logger/file_log_sink.cpp index 1654892..74b9304 100644 --- a/include/gpufl/core/logger/file_log_sink.cpp +++ b/include/gpufl/core/logger/file_log_sink.cpp @@ -8,6 +8,7 @@ #include "gpufl/core/logger/file_compressor.hpp" #include "gpufl/core/logger/log_rotator.hpp" #include "gpufl/core/logger/log_salvage.hpp" +#include "gpufl/core/logger/session_ownership.hpp" namespace gpufl { namespace fs = std::filesystem; @@ -61,6 +62,9 @@ void FileLogSink::FileChannel::close() { } void FileLogSink::FileChannel::closeLocked() { + const WindowTiming timing{ + window_first_write_ms_, + window_first_write_ms_ >= 0 ? nowMs() : -1}; if (stream_.is_open()) { stream_.flush(); stream_.close(); @@ -79,7 +83,7 @@ void FileLogSink::FileChannel::closeLocked() { if (next_window_index_ == 0) { next_window_index_ = rotator_->nextWindowIndex(); } - (void)rotator_->compressActive(next_window_index_); + (void)rotator_->compressActive(next_window_index_, timing); } opened_ = false; } @@ -156,6 +160,7 @@ void FileLogSink::FileChannel::rotateLocked(RotateTrigger trigger) { next_window_index_ = rotator_->nextWindowIndex(); } const std::size_t index = next_window_index_; + const WindowTiming timing{window_first_write_ms_, nowMs()}; const auto result = rotator_->retireActiveWindow(index); const char* trigger_name = trigger == RotateTrigger::Size ? "size" : "time"; @@ -178,7 +183,9 @@ void FileLogSink::FileChannel::rotateLocked(RotateTrigger trigger) { ensureOpenLocked(); // fresh, empty active window // Enqueue AFTER reopening so the channel is immediately // writable again even if the worker starts exporting at once. - if (owner_) owner_->enqueueRetired(this, index, retired_bytes); + if (owner_) { + owner_->enqueueRetired(this, index, retired_bytes, timing); + } return; } case LogFileRotator::RetireResult::Blocked: @@ -193,14 +200,16 @@ void FileLogSink::FileChannel::rotateLocked(RotateTrigger trigger) { ensureOpenLocked(); } -void FileLogSink::FileChannel::exportRetired(const std::size_t index) { +void FileLogSink::FileChannel::exportRetired( + const std::size_t index, const WindowTiming timing) { if (opt_.before_retired_export) opt_.before_retired_export(); const auto started = std::chrono::steady_clock::now(); std::size_t pruned = 0; // No channel lock held: the retired file is immutable and nothing // writes to it any more, so gzip and the publish backoff cost this // worker thread only. - const auto result = rotator_->exportRetiredWindow(index, &pruned); + const auto result = + rotator_->exportRetiredWindow(index, &pruned, timing); const auto elapsed_ms = std::chrono::duration_cast( std::chrono::steady_clock::now() - started) @@ -314,6 +323,23 @@ FileLogSink::RotationStats FileLogSink::FileChannel::rotationStats() const { FileLogSink::FileLogSink(const Logger::Options& opt) { if (opt.base_path.empty()) return; + if (opt.session_id.empty()) { + GFL_LOG_ERROR("FileLogSink: session_id is required for session " + "ownership."); + return; + } + const fs::path session_dir = + fs::path(opt.base_path) / opt.session_id; + std::string lock_error; + session_ownership_ = + SessionOwnershipLock::tryAcquire(session_dir, &lock_error); + if (!session_ownership_) { + GFL_LOG_ERROR("FileLogSink: cannot own session directory '", + session_dir.string(), "': ", lock_error, + ". Refusing to open channels so two live processes " + "cannot mutate the same spool."); + return; + } chanDevice_ = std::make_unique("device", opt, this); chanScope_ = std::make_unique("scope", opt, this); chanSystem_ = std::make_unique("system", opt, this); @@ -370,7 +396,8 @@ void FileLogSink::rotateDueWindows() { void FileLogSink::enqueueRetired(FileChannel* channel, const std::size_t index, - const std::uint64_t bytes) { + const std::uint64_t bytes, + const WindowTiming timing) { if (!channel) return; std::lock_guard lk(retire_mu_); if (retire_stop_) { @@ -382,7 +409,7 @@ void FileLogSink::enqueueRetired(FileChannel* channel, "window ", index, " in `.tmp` for salvage."); return; } - retire_queue_.push_back({channel, index, bytes}); + retire_queue_.push_back({channel, index, bytes, timing}); ++pending_exports_; pending_export_bytes_ += bytes; max_pending_exports_ = @@ -412,7 +439,7 @@ void FileLogSink::enqueueRetired(FileChannel* channel, ++exports_in_flight_; } // Outside every lock: gzip + publish retries live here. - item.channel->exportRetired(item.index); + item.channel->exportRetired(item.index, item.timing); { std::lock_guard lk(retire_mu_); --exports_in_flight_; @@ -464,7 +491,7 @@ void FileLogSink::close() { // launcher's salvage pass otherwise). if (!temp_dir_.empty()) { const fs::path session_dir = fs::path(temp_dir_).parent_path(); - const auto salvage = salvageSessionTempDir(session_dir); + const auto salvage = salvageOwnedSessionTempDir(session_dir); if (salvage.lost_windows > 0) { // Terminal: those events are gone. Say so where an operator will // see it AND keep it in the stats, because everything downstream @@ -484,6 +511,7 @@ void FileLogSink::close() { salvage.salvaged, ", deferred=", salvage.deferred, ") - leaving it for the next salvage pass."); temp_dir_.clear(); + session_ownership_.reset(); return; } std::error_code ec; @@ -495,6 +523,9 @@ void FileLogSink::close() { } temp_dir_.clear(); } + // Release only after every active/raw/staged artifact has been reconciled + // and `.tmp` has either been removed or deliberately left visible. + session_ownership_.reset(); } FileLogSink::FileChannel* FileLogSink::resolveChannel(Channel ch) const { diff --git a/include/gpufl/core/logger/file_log_sink.hpp b/include/gpufl/core/logger/file_log_sink.hpp index 41c9a94..4061a68 100644 --- a/include/gpufl/core/logger/file_log_sink.hpp +++ b/include/gpufl/core/logger/file_log_sink.hpp @@ -12,11 +12,13 @@ #include "gpufl/core/logger/log_sink.hpp" #include "gpufl/core/logger/logger.hpp" +#include "gpufl/core/logger/window_metadata.hpp" namespace gpufl { class IFileCompressor; class LogFileRotator; +class SessionOwnershipLock; /** * Sink that writes NDJSON lines to per-channel files on disk. @@ -139,7 +141,7 @@ class FileLogSink final : public ILogSink { * touches files nothing writes to any more - and takes the lock * just to fold the outcome into the stats. */ - void exportRetired(std::size_t index); + void exportRetired(std::size_t index, WindowTiming timing); private: void ensureOpenLocked(); @@ -184,13 +186,17 @@ class FileLogSink final : public ILogSink { * spawn a thread. */ void enqueueRetired(FileChannel* channel, std::size_t index, - std::uint64_t bytes); + std::uint64_t bytes, WindowTiming timing); void stopRetirementWorker(); std::unique_ptr chanDevice_; std::unique_ptr chanScope_; std::unique_ptr chanSystem_; std::unique_ptr chanSass_; + // Held for the complete writer lifetime. Root windows remain readable to + // the agent, but no other process may salvage `.tmp` or finalize this + // session until the handle is released. + std::unique_ptr session_ownership_; // The shared session `.tmp` dir, removed once in close() after every // channel has finalized (its own actives would block earlier removal). std::string temp_dir_; @@ -204,6 +210,7 @@ class FileLogSink final : public ILogSink { FileChannel* channel; std::size_t index; std::uint64_t bytes; + WindowTiming timing; }; mutable std::mutex retire_mu_; std::condition_variable retire_cv_; diff --git a/include/gpufl/core/logger/log_rotator.cpp b/include/gpufl/core/logger/log_rotator.cpp index 0b59182..6592319 100644 --- a/include/gpufl/core/logger/log_rotator.cpp +++ b/include/gpufl/core/logger/log_rotator.cpp @@ -7,6 +7,7 @@ #include "gpufl/core/debug_logger.hpp" #include "gpufl/core/logger/log_salvage.hpp" +#include "gpufl/core/logger/window_metadata.hpp" namespace gpufl { namespace fs = std::filesystem; @@ -104,7 +105,8 @@ LogFileRotator::RetireResult LogFileRotator::retireActiveWindow( } LogFileRotator::ExportWindowResult LogFileRotator::exportRetiredWindow( - const std::size_t index, std::size_t* pruned_windows) const { + const std::size_t index, std::size_t* pruned_windows, + const WindowTiming& timing) const { const std::string retired = retiredPath(index); std::error_code ec; if (!fs::exists(retired, ec)) return ExportWindowResult::NoData; @@ -122,9 +124,20 @@ LogFileRotator::ExportWindowResult LogFileRotator::exportRetiredWindow( }; if (!compressor_) { - if (!publishWithRetry_(retired, rotatedPath(index))) { + const std::string published = rotatedPath(index); + // Identity must become visible BEFORE the payload. The agent polls + // the session root concurrently; publishing the payload first opens + // a race where a current-client window looks legacy and bypasses + // checksum/idempotency headers. + if (!ensureWindowMetadata( + fs::path(sessionDir()), opt_.session_id, opt_.channel_name, + index, retired, timing)) { + return ExportWindowResult::StagedForSalvage; + } + if (!publishWithRetry_(retired, published)) { // The retired file is still in `.tmp`, indexed and complete - - // the salvage pass publishes it. + // the salvage pass publishes it. Its sidecar is an intentional + // tombstone and must match this same staged payload. return ExportWindowResult::StagedForSalvage; } prune(); @@ -176,7 +189,15 @@ LogFileRotator::ExportWindowResult LogFileRotator::exportRetiredWindow( return ExportWindowResult::StagedForSalvage; } - if (!publishWithRetry_(staging, rotatedPath(index) + ".gz")) { + const std::string published = rotatedPath(index) + ".gz"; + // Same ordering invariant as the uncompressed path: once `published` + // appears in the session root, its immutable identity already exists. + if (!ensureWindowMetadata( + fs::path(sessionDir()), opt_.session_id, opt_.channel_name, index, + staging, timing)) { + return ExportWindowResult::StagedForSalvage; + } + if (!publishWithRetry_(staging, published)) { return ExportWindowResult::StagedForSalvage; } prune(); @@ -209,8 +230,20 @@ LogFileRotator::ExportWindowResult LogFileRotator::rotate( } LogFileRotator::ExportWindowResult LogFileRotator::compressActive( - const std::size_t index) const { - const ExportWindowResult result = exportWindowAt_(index, nullptr); + const std::size_t index, const WindowTiming& timing) const { + const auto retired = retireActiveWindow(index); + ExportWindowResult result = ExportWindowResult::DeferredInActive; + switch (retired) { + case RetireResult::NoData: + result = ExportWindowResult::NoData; + break; + case RetireResult::Blocked: + result = ExportWindowResult::DeferredInActive; + break; + case RetireResult::Retired: + result = exportRetiredWindow(index, nullptr, timing); + break; + } // Best-effort removal of this channel's (now exported) active file. // If exportWindow_ deferred in the active file, leave it for the salvage // path instead of deleting the only copy of the window. diff --git a/include/gpufl/core/logger/log_rotator.hpp b/include/gpufl/core/logger/log_rotator.hpp index 2ec7167..8744773 100644 --- a/include/gpufl/core/logger/log_rotator.hpp +++ b/include/gpufl/core/logger/log_rotator.hpp @@ -4,6 +4,7 @@ #include #include "gpufl/core/logger/file_compressor.hpp" +#include "gpufl/core/logger/window_metadata.hpp" namespace gpufl { @@ -109,7 +110,8 @@ class LogFileRotator { * publish retry/backoff for transient holders lives here. */ ExportWindowResult exportRetiredWindow(std::size_t index, - std::size_t* pruned_windows) const; + std::size_t* pruned_windows, + const WindowTiming& timing = {}) const; /** * Finalize this channel on clean shutdown (FileLogSink::close → @@ -126,7 +128,8 @@ class LogFileRotator { * already have been acknowledged and removed, but their indices remain * consumed for the lifetime of the session. */ - ExportWindowResult compressActive(std::size_t index) const; + ExportWindowResult compressActive( + std::size_t index, const WindowTiming& timing = {}) const; /** * The session temp dir: `//.tmp`. Removed diff --git a/include/gpufl/core/logger/log_salvage.cpp b/include/gpufl/core/logger/log_salvage.cpp index 61f5dcc..b782b81 100644 --- a/include/gpufl/core/logger/log_salvage.cpp +++ b/include/gpufl/core/logger/log_salvage.cpp @@ -35,6 +35,8 @@ #include "gpufl/core/debug_logger.hpp" #include "gpufl/core/logger/file_compressor.hpp" +#include "gpufl/core/logger/session_ownership.hpp" +#include "gpufl/core/logger/window_metadata.hpp" namespace gpufl { namespace fs = std::filesystem; @@ -444,6 +446,7 @@ std::size_t nextLogWindowIndex(const fs::path& session_dir, std::size_t max_index = 0; scanMaxIndex(session_dir / ".tmp", channel, max_index); scanMaxIndex(session_dir, channel, max_index); + scanWindowMetadataMaxSequence(session_dir, channel, max_index); return max_index + 1; } @@ -468,7 +471,7 @@ std::size_t pruneLogWindows(const fs::path& session_dir, return removed; } -LogSalvageResult salvageSessionTempDir(const fs::path& session_dir) { +LogSalvageResult salvageOwnedSessionTempDir(const fs::path& session_dir) { LogSalvageResult result; // A prior pass may already have discarded an unrecoverable artifact. // Count the durable marker even when `.tmp` is gone so an uploader that @@ -654,6 +657,12 @@ LogSalvageResult salvageSessionTempDir(const fs::path& session_dir) { ++result.deferred; continue; } + if (!ensureWindowMetadata( + session_dir, session_dir.filename().string(), channel, + idx, path)) { + ++result.deferred; + continue; + } std::error_code mv_ec; const auto moved = moveFileNoReplace(path, target, mv_ec); if (moved != MoveFileNoReplaceResult::Moved) { @@ -739,6 +748,12 @@ LogSalvageResult salvageSessionTempDir(const fs::path& session_dir) { ++result.deferred; continue; } + if (!ensureWindowMetadata( + session_dir, session_dir.filename().string(), channel, idx, + staging)) { + ++result.deferred; + continue; + } std::error_code publish_ec; const auto published = moveFileNoReplace(staging, target, publish_ec); @@ -757,6 +772,22 @@ LogSalvageResult salvageSessionTempDir(const fs::path& session_dir) { return result; } +LogSalvageResult salvageSessionTempDir(const fs::path& session_dir) { + std::string lock_error; + auto ownership = + SessionOwnershipLock::tryAcquire(session_dir, &lock_error); + if (!ownership) { + LogSalvageResult result; + result.active_sessions_skipped = 1; + result.lost_windows = + static_cast(transportLossMarkerCount(session_dir)); + GFL_LOG_DEBUG("[Logger] salvage skipped active session '", + session_dir.string(), "': ", lock_error); + return result; + } + return salvageOwnedSessionTempDir(session_dir); +} + LogSalvageResult salvageSessionTempDirs(const fs::path& root) { LogSalvageResult total; std::error_code ec; @@ -770,6 +801,7 @@ LogSalvageResult salvageSessionTempDirs(const fs::path& root) { total.salvaged += r.salvaged; total.deferred += r.deferred; total.lost_windows += r.lost_windows; + total.active_sessions_skipped += r.active_sessions_skipped; } return total; } diff --git a/include/gpufl/core/logger/log_salvage.hpp b/include/gpufl/core/logger/log_salvage.hpp index bdc23c3..6e8c1a0 100644 --- a/include/gpufl/core/logger/log_salvage.hpp +++ b/include/gpufl/core/logger/log_salvage.hpp @@ -24,6 +24,12 @@ struct LogSalvageResult { * unreported loss here looks exactly like a clean session downstream. */ int lost_windows = 0; + /** + * Session directories deliberately not touched because another live + * process owns their OS lock. This is not a salvage failure and must not + * be treated as an orphan or completion signal. + */ + int active_sessions_skipped = 0; }; /** @@ -92,6 +98,13 @@ std::size_t pruneLogWindows(const std::filesystem::path& session_dir, LogSalvageResult salvageSessionTempDir( const std::filesystem::path& session_dir); +/** + * Salvage one session while its writer-owned SessionOwnershipLock is held by + * the caller. Only FileLogSink's clean-shutdown path may use this bypass. + */ +LogSalvageResult salvageOwnedSessionTempDir( + const std::filesystem::path& session_dir); + /** Apply salvageSessionTempDir() to each session directory under `root`. */ LogSalvageResult salvageSessionTempDirs( const std::filesystem::path& root); diff --git a/include/gpufl/core/logger/session_ownership.cpp b/include/gpufl/core/logger/session_ownership.cpp new file mode 100644 index 0000000..d0de709 --- /dev/null +++ b/include/gpufl/core/logger/session_ownership.cpp @@ -0,0 +1,203 @@ +#include "gpufl/core/logger/session_ownership.hpp" + +#include +#include +#include +#include +#include + +#if defined(_WIN32) +#ifndef NOMINMAX +#define NOMINMAX +#endif +#include +#else +#include +#include +#endif + +namespace gpufl { +namespace fs = std::filesystem; + +namespace { +std::mutex g_owned_sessions_mu; +std::set g_owned_sessions; + +std::string ownershipKey(const fs::path& path) { + std::error_code ec; + fs::path normalized = fs::weakly_canonical(path, ec); + if (ec) { + ec.clear(); + normalized = fs::absolute(path, ec); + if (ec) normalized = path; + } + return normalized.lexically_normal().generic_string(); +} + +bool reserveInProcess(const std::string& key) { + std::lock_guard guard(g_owned_sessions_mu); + return g_owned_sessions.insert(key).second; +} + +void releaseInProcess(const std::string& key) noexcept { + if (key.empty()) return; + std::lock_guard guard(g_owned_sessions_mu); + g_owned_sessions.erase(key); +} +} // namespace + +std::unique_ptr SessionOwnershipLock::tryAcquire( + const fs::path& session_dir, std::string* error) { + if (error) error->clear(); + std::error_code dir_ec; + fs::create_directories(session_dir, dir_ec); + if (dir_ec) { + if (error) { + *error = "cannot create session directory: " + dir_ec.message(); + } + return nullptr; + } + + auto lock = std::unique_ptr( + new SessionOwnershipLock()); + lock->path_ = session_dir / kFilename; + lock->registry_key_ = ownershipKey(lock->path_); + if (!reserveInProcess(lock->registry_key_)) { + if (error) *error = "owned by another live process"; + return nullptr; + } + +#if defined(_WIN32) + HANDLE handle = ::CreateFileW( + lock->path_.c_str(), GENERIC_READ | GENERIC_WRITE, + FILE_SHARE_READ | FILE_SHARE_WRITE | FILE_SHARE_DELETE, nullptr, + OPEN_ALWAYS, FILE_ATTRIBUTE_NORMAL, nullptr); + if (handle == INVALID_HANDLE_VALUE) { + if (error) { + *error = std::system_category() + .message(static_cast(::GetLastError())); + } + lock->release(); + return nullptr; + } + + OVERLAPPED overlapped{}; + if (!::LockFileEx(handle, + LOCKFILE_EXCLUSIVE_LOCK | LOCKFILE_FAIL_IMMEDIATELY, + 0, 1, 0, &overlapped)) { + const DWORD code = ::GetLastError(); + ::CloseHandle(handle); + if (error) { + *error = code == ERROR_LOCK_VIOLATION + ? "owned by another live process" + : std::system_category().message( + static_cast(code)); + } + lock->release(); + return nullptr; + } + lock->handle_ = handle; +#else + const int fd = + ::open(lock->path_.c_str(), O_CREAT | O_RDWR | O_CLOEXEC, 0600); + if (fd < 0) { + if (error) *error = std::strerror(errno); + lock->release(); + return nullptr; + } + struct flock file_lock {}; + file_lock.l_type = F_WRLCK; + file_lock.l_whence = SEEK_SET; + file_lock.l_start = 0; + file_lock.l_len = 0; + if (::fcntl(fd, F_SETLK, &file_lock) != 0) { + const int code = errno; + ::close(fd); + if (error) { + *error = (code == EACCES || code == EAGAIN) + ? "owned by another live process" + : std::strerror(code); + } + lock->release(); + return nullptr; + } + lock->fd_ = fd; +#endif + return lock; +} + +SessionOwnershipLock::~SessionOwnershipLock() { release(); } + +SessionOwnershipLock::SessionOwnershipLock( + SessionOwnershipLock&& other) noexcept + : path_(std::move(other.path_)), + registry_key_(std::move(other.registry_key_)) +#if defined(_WIN32) + , + handle_(other.handle_) +#else + , + fd_(other.fd_) +#endif +{ + other.registry_key_.clear(); +#if defined(_WIN32) + other.handle_ = nullptr; +#else + other.fd_ = -1; +#endif +} + +SessionOwnershipLock& SessionOwnershipLock::operator=( + SessionOwnershipLock&& other) noexcept { + if (this == &other) return *this; + release(); + path_ = std::move(other.path_); + registry_key_ = std::move(other.registry_key_); + other.registry_key_.clear(); +#if defined(_WIN32) + handle_ = other.handle_; + other.handle_ = nullptr; +#else + fd_ = other.fd_; + other.fd_ = -1; +#endif + return *this; +} + +bool SessionOwnershipLock::owns() const noexcept { +#if defined(_WIN32) + return handle_ != nullptr; +#else + return fd_ >= 0; +#endif +} + +const fs::path& SessionOwnershipLock::path() const noexcept { return path_; } + +void SessionOwnershipLock::release() noexcept { +#if defined(_WIN32) + if (handle_) { + OVERLAPPED overlapped{}; + (void)::UnlockFileEx(static_cast(handle_), 0, 1, 0, + &overlapped); + (void)::CloseHandle(static_cast(handle_)); + handle_ = nullptr; + } +#else + if (fd_ >= 0) { + struct flock file_lock {}; + file_lock.l_type = F_UNLCK; + file_lock.l_whence = SEEK_SET; + file_lock.l_start = 0; + file_lock.l_len = 0; + (void)::fcntl(fd_, F_SETLK, &file_lock); + (void)::close(fd_); + fd_ = -1; + } +#endif + releaseInProcess(registry_key_); + registry_key_.clear(); +} + +} // namespace gpufl diff --git a/include/gpufl/core/logger/session_ownership.hpp b/include/gpufl/core/logger/session_ownership.hpp new file mode 100644 index 0000000..efd8f09 --- /dev/null +++ b/include/gpufl/core/logger/session_ownership.hpp @@ -0,0 +1,55 @@ +#pragma once + +#include +#include +#include + +namespace gpufl { + +/** + * Process-lifetime ownership of one session spool directory. + * + * The lock is an OS advisory lock, not a PID-file convention: the kernel + * releases it when the process exits or crashes. Finished root windows remain + * readable while the lock is held; only operations that mutate `.tmp` or + * declare the session complete must acquire ownership. + */ +class SessionOwnershipLock { + public: + ~SessionOwnershipLock(); + + SessionOwnershipLock(const SessionOwnershipLock&) = delete; + SessionOwnershipLock& operator=(const SessionOwnershipLock&) = delete; + + SessionOwnershipLock(SessionOwnershipLock&&) noexcept; + SessionOwnershipLock& operator=(SessionOwnershipLock&&) noexcept; + + /** + * Try to acquire exclusive ownership without waiting. + * + * Returns null when another live process owns the session or when the lock + * file cannot be opened. `error` receives an operator-readable reason. + */ + static std::unique_ptr tryAcquire( + const std::filesystem::path& session_dir, + std::string* error = nullptr); + + [[nodiscard]] bool owns() const noexcept; + [[nodiscard]] const std::filesystem::path& path() const noexcept; + + static constexpr const char* kFilename = ".gpufl-session.lock"; + + private: + SessionOwnershipLock() = default; + void release() noexcept; + + std::filesystem::path path_; + std::string registry_key_; +#if defined(_WIN32) + void* handle_ = nullptr; +#else + int fd_ = -1; +#endif +}; + +} // namespace gpufl diff --git a/include/gpufl/core/logger/window_metadata.cpp b/include/gpufl/core/logger/window_metadata.cpp new file mode 100644 index 0000000..17785c9 --- /dev/null +++ b/include/gpufl/core/logger/window_metadata.cpp @@ -0,0 +1,236 @@ +#include "gpufl/core/logger/window_metadata.hpp" + +#include +#include +#include +#include +#include +#include +#include +#include + +#include + +#include "gpufl/core/debug_logger.hpp" +#include "gpufl/core/json/json.hpp" +#include "gpufl/core/logger/log_salvage.hpp" + +namespace gpufl { +namespace fs = std::filesystem; +namespace { + +std::string generateUuidV4() { + std::array bytes{}; + std::random_device random; + for (auto& byte : bytes) { + byte = static_cast(random()); + } + bytes[6] = static_cast((bytes[6] & 0x0fU) | 0x40U); + bytes[8] = static_cast((bytes[8] & 0x3fU) | 0x80U); + + std::ostringstream out; + out << std::hex << std::setfill('0'); + for (std::size_t i = 0; i < bytes.size(); ++i) { + if (i == 4 || i == 6 || i == 8 || i == 10) out << '-'; + out << std::setw(2) << static_cast(bytes[i]); + } + return out.str(); +} + +std::string jsonEscape(const std::string& value) { + std::string escaped; + escaped.reserve(value.size()); + for (const char c : value) { + switch (c) { + case '\\': escaped += "\\\\"; break; + case '"': escaped += "\\\""; break; + case '\n': escaped += "\\n"; break; + case '\r': escaped += "\\r"; break; + case '\t': escaped += "\\t"; break; + default: escaped += c; break; + } + } + return escaped; +} + +bool payloadFingerprint(const fs::path& payload, std::uint64_t& bytes, + std::uint32_t& checksum) { + std::ifstream input(payload, std::ios::binary); + if (!input) return false; + uLong crc = crc32(0L, Z_NULL, 0); + bytes = 0; + std::array buffer{}; + while (input) { + input.read(reinterpret_cast(buffer.data()), buffer.size()); + const auto count = input.gcount(); + if (count <= 0) continue; + crc = crc32(crc, buffer.data(), static_cast(count)); + bytes += static_cast(count); + } + if (input.bad()) return false; + checksum = static_cast(crc); + return true; +} + +bool existingMetadataMatches( + const fs::path& metadata_path, + const std::string& session_id, + const std::string& channel, + const std::size_t sequence, + const fs::path& payload, + const std::uint64_t payload_bytes, + const std::uint32_t payload_crc32) { + const auto metadata = json::loadFile(metadata_path.string()); + constexpr std::uint64_t kMissing = + std::numeric_limits::max(); + if (!metadata.is_object() || + metadata.value("type", "") != "transport_window" || + metadata.value("window_id", "").empty() || + metadata.value("session_id", "") != session_id || + metadata.value("channel", "") != channel || + metadata.value("window_sequence", kMissing) != + sequence || + metadata.value("payload_file", "") != + payload.filename().string() || + metadata.value("payload_bytes", kMissing) != + payload_bytes || + metadata.value("payload_crc32", kMissing) != + payload_crc32) { + GFL_LOG_ERROR( + "[Logger] immutable metadata '", metadata_path.string(), + "' does not describe the payload waiting to claim its window " + "sequence; refusing to publish either identity."); + return false; + } + return true; +} + +} // namespace + +fs::path windowMetadataPath(const fs::path& session_dir, + const std::string& channel, + const std::size_t sequence) { + return session_dir / + (".gpufl-window." + channel + "." + std::to_string(sequence) + + ".json"); +} + +bool ensureWindowMetadata(const fs::path& session_dir, + const std::string& session_id, + const std::string& channel, + const std::size_t sequence, + const fs::path& payload, + const WindowTiming& timing) { + const fs::path target = + windowMetadataPath(session_dir, channel, sequence); + std::uint64_t payload_bytes = 0; + std::uint32_t payload_crc32 = 0; + if (!payloadFingerprint(payload, payload_bytes, payload_crc32)) { + GFL_LOG_ERROR("[Logger] cannot fingerprint window payload '", + payload.string(), "'; metadata not published."); + return false; + } + + std::error_code state_ec; + if (fs::is_regular_file(target, state_ec)) { + return existingMetadataMatches( + target, session_id, channel, sequence, payload, payload_bytes, + payload_crc32); + } + + WindowMetadata metadata; + metadata.window_id = generateUuidV4(); + metadata.session_id = session_id; + metadata.channel = channel; + metadata.window_sequence = sequence; + metadata.timing = timing; + metadata.created_wall_ms = + std::chrono::duration_cast( + std::chrono::system_clock::now().time_since_epoch()) + .count(); + metadata.payload_file = payload.filename().string(); + metadata.payload_bytes = payload_bytes; + metadata.payload_crc32 = payload_crc32; + + const fs::path partial = + target.string() + ".part." + metadata.window_id; + { + std::ofstream out(partial, std::ios::binary | std::ios::trunc); + if (!out) return false; + out << "{\"schema_version\":1,\"type\":\"transport_window\"," + << "\"window_id\":\"" << metadata.window_id << "\"," + << "\"session_id\":\"" << jsonEscape(metadata.session_id) + << "\",\"channel\":\"" << jsonEscape(metadata.channel) + << "\",\"window_sequence\":" << metadata.window_sequence + << ",\"opened_mono_ms\":" << metadata.timing.opened_mono_ms + << ",\"closed_mono_ms\":" << metadata.timing.closed_mono_ms + << ",\"created_wall_ms\":" << metadata.created_wall_ms + << ",\"payload_file\":\"" + << jsonEscape(metadata.payload_file) + << "\",\"payload_bytes\":" << metadata.payload_bytes + << ",\"payload_crc32\":" << metadata.payload_crc32 << "}\n"; + out.flush(); + if (!out.good()) { + out.close(); + fs::remove(partial, state_ec); + return false; + } + } + + std::error_code move_ec; + const auto moved = moveFileNoReplace(partial, target, move_ec); + if (moved == MoveFileNoReplaceResult::Moved) { + fs::remove(partial, state_ec); + return true; + } + if (moved == MoveFileNoReplaceResult::DestinationExists) { + fs::remove(partial, state_ec); + std::error_code target_ec; + if (fs::is_regular_file(target, target_ec)) { + return existingMetadataMatches( + target, session_id, channel, sequence, payload, + payload_bytes, payload_crc32); + } + GFL_LOG_ERROR("[Logger] immutable window metadata path '", + target.string(), + "' exists but is not a regular file."); + return false; + } + fs::remove(partial, state_ec); + GFL_LOG_ERROR("[Logger] cannot publish immutable window metadata '", + target.string(), "': ", move_ec.message()); + return false; +} + +void scanWindowMetadataMaxSequence(const fs::path& session_dir, + const std::string& channel, + std::size_t& max_sequence) { + const std::string prefix = ".gpufl-window." + channel + "."; + constexpr const char* suffix = ".json"; + std::error_code ec; + if (!fs::is_directory(session_dir, ec)) return; + for (const auto& entry : fs::directory_iterator(session_dir, ec)) { + std::error_code file_ec; + if (!entry.is_regular_file(file_ec)) continue; + const std::string name = entry.path().filename().string(); + if (name.rfind(prefix, 0) != 0 || + name.size() <= prefix.size() + std::char_traits::length(suffix) || + name.compare(name.size() - std::char_traits::length(suffix), + std::char_traits::length(suffix), suffix) != 0) { + continue; + } + const std::size_t count = + name.size() - prefix.size() - + std::char_traits::length(suffix); + try { + const auto sequence = + static_cast( + std::stoull(name.substr(prefix.size(), count))); + max_sequence = std::max(max_sequence, sequence); + } catch (...) { + // Ignore unrelated dot-files. + } + } +} + +} // namespace gpufl diff --git a/include/gpufl/core/logger/window_metadata.hpp b/include/gpufl/core/logger/window_metadata.hpp new file mode 100644 index 0000000..1fc6fe4 --- /dev/null +++ b/include/gpufl/core/logger/window_metadata.hpp @@ -0,0 +1,52 @@ +#pragma once + +#include +#include +#include +#include + +namespace gpufl { + +struct WindowTiming { + /** Session/process monotonic clock. Valid only within this run. */ + std::int64_t opened_mono_ms = -1; + std::int64_t closed_mono_ms = -1; +}; + +struct WindowMetadata { + std::string window_id; + std::string session_id; + std::string channel; + std::size_t window_sequence = 0; + WindowTiming timing; + std::int64_t created_wall_ms = 0; + std::string payload_file; + std::uint64_t payload_bytes = 0; + std::uint32_t payload_crc32 = 0; +}; + +/** + * Immutable sidecar and post-ACK tombstone for one transport window. + * + * The payload may later be deleted, but this small file remains until the + * session is retired. That keeps the sequence consumed and gives the agent a + * stable idempotency key independent of filename timestamps. + */ +bool ensureWindowMetadata(const std::filesystem::path& session_dir, + const std::string& session_id, + const std::string& channel, + std::size_t sequence, + const std::filesystem::path& payload, + const WindowTiming& timing = {}); + +std::filesystem::path windowMetadataPath( + const std::filesystem::path& session_dir, + const std::string& channel, + std::size_t sequence); + +/** Include metadata tombstones when restoring the next channel sequence. */ +void scanWindowMetadataMaxSequence(const std::filesystem::path& session_dir, + const std::string& channel, + std::size_t& max_sequence); + +} // namespace gpufl diff --git a/tests/core/test_file_log_sink_rotation.cpp b/tests/core/test_file_log_sink_rotation.cpp index bed65c3..6429b09 100644 --- a/tests/core/test_file_log_sink_rotation.cpp +++ b/tests/core/test_file_log_sink_rotation.cpp @@ -26,6 +26,8 @@ #include "gpufl/core/logger/file_log_sink.hpp" #include "gpufl/core/logger/log_rotator.hpp" #include "gpufl/core/logger/log_salvage.hpp" +#include "gpufl/core/logger/session_ownership.hpp" +#include "gpufl/core/logger/window_metadata.hpp" #include "gpufl/core/logger/log_sink.hpp" #include "gpufl/core/logger/logger.hpp" @@ -807,6 +809,170 @@ TEST_F(FileLogSinkRotationTest, PruneOnPublishIsCountedAsDataLoss) { EXPECT_TRUE(fs::exists(sessionDir() / "device.3.log.gz")); } +TEST_F(FileLogSinkRotationTest, SessionOwnershipIsExclusiveAndCrashReleased) { + std::string first_error; + auto first = + gpufl::SessionOwnershipLock::tryAcquire(sessionDir(), &first_error); + ASSERT_NE(first, nullptr) << first_error; + + std::string second_error; + auto second = + gpufl::SessionOwnershipLock::tryAcquire(sessionDir(), &second_error); + EXPECT_EQ(second, nullptr); + EXPECT_NE(second_error.find("owned by another live process"), + std::string::npos); + + first.reset(); + auto after_release = + gpufl::SessionOwnershipLock::tryAcquire(sessionDir(), &second_error); + EXPECT_NE(after_release, nullptr) << second_error; +} + +TEST_F(FileLogSinkRotationTest, SalvageNeverTouchesALiveOwnedSession) { + fs::create_directories(sessionDir() / ".tmp"); + writeText(sessionDir() / ".tmp" / "device.1.log", + "payload-from-live-writer\n"); + + auto owner = gpufl::SessionOwnershipLock::tryAcquire(sessionDir()); + ASSERT_NE(owner, nullptr); + + const auto while_live = gpufl::salvageSessionTempDir(sessionDir()); + EXPECT_EQ(while_live.active_sessions_skipped, 1); + EXPECT_EQ(while_live.salvaged, 0); + EXPECT_TRUE(fs::exists(sessionDir() / ".tmp" / "device.1.log")); + EXPECT_FALSE(fs::exists(sessionDir() / "device.1.log.gz")); + + owner.reset(); + const auto after_exit = gpufl::salvageSessionTempDir(sessionDir()); + EXPECT_EQ(after_exit.active_sessions_skipped, 0); + EXPECT_EQ(after_exit.salvaged, 1); + EXPECT_TRUE(fs::exists(sessionDir() / "device.1.log.gz")); +} + +TEST_F(FileLogSinkRotationTest, PublishedWindowHasImmutableIdentityMetadata) { + { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + fake_now_ms_ = 100; + sink.write(gpufl::Channel::Device, R"({"event":1})"); + fake_now_ms_ = 5100; + sink.rotateDueWindows(); + sink.waitForPendingExports(); + } + + const fs::path metadata = + gpufl::windowMetadataPath(sessionDir(), "device", 1); + ASSERT_TRUE(fs::exists(metadata)); + std::ifstream input(metadata, std::ios::binary); + const std::string json( + (std::istreambuf_iterator(input)), + std::istreambuf_iterator()); + EXPECT_NE(json.find(R"("type":"transport_window")"), + std::string::npos); + EXPECT_NE(json.find(R"("window_sequence":1)"), + std::string::npos); + EXPECT_NE(json.find(R"("opened_mono_ms":100)"), + std::string::npos); + EXPECT_NE(json.find(R"("closed_mono_ms":5100)"), + std::string::npos); + EXPECT_NE(json.find(R"("payload_crc32":)"), std::string::npos); +} + +TEST_F(FileLogSinkRotationTest, + MetadataFailureKeepsPayloadStagedAndInvisibleToTheAgent) { + // A directory at the immutable sidecar name is a deterministic, + // cross-platform publication failure. It must not be mistaken for an + // already-published metadata file or silently downgrade this window to + // the legacy, non-idempotent upload path. + const fs::path metadata = + gpufl::windowMetadataPath(sessionDir(), "device", 1); + ASSERT_TRUE(fs::create_directories(metadata)); + + { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + fake_now_ms_ = 100; + sink.write(gpufl::Channel::Device, R"({"event":1})"); + fake_now_ms_ = 5100; + sink.rotateDueWindows(); + sink.waitForPendingExports(); + } + + EXPECT_FALSE(fs::exists(sessionDir() / "device.1.log.gz")) + << "a current-client payload must never become visible without its " + "identity sidecar"; + EXPECT_TRUE(fs::exists(tmpDir() / "device.1.log.gz")) + << "the complete payload is recoverable once metadata publication " + "can succeed"; + EXPECT_EQ(gpufl::transportLossMarkerCount(sessionDir()), 0u) + << "metadata publication failure is deferred, not data loss"; +} + +TEST_F(FileLogSinkRotationTest, + FailedPayloadPublishStillLeavesIdentityAheadOfTheStagedWindow) { + // Occupy the final payload name so the no-replace publish fails after + // metadata creation. This pins the ordering contract without racing a + // polling thread: moving metadata after publish makes this test fail. + std::promise worker_entered_promise; + auto worker_entered = worker_entered_promise.get_future(); + std::promise release_worker_promise; + auto release_worker = release_worker_promise.get_future().share(); + auto opt = options(/*rotate_after_ms=*/5000); + opt.before_retired_export = [&] { + worker_entered_promise.set_value(); + release_worker.wait(); + }; + + { + gpufl::FileLogSink sink(std::move(opt)); + fake_now_ms_ = 100; + sink.write(gpufl::Channel::Device, R"({"event":"new"})"); + fake_now_ms_ = 5100; + sink.rotateDueWindows(); + ASSERT_EQ(worker_entered.wait_for(std::chrono::seconds(2)), + std::future_status::ready); + writeText(sessionDir() / "device.1.log.gz", "older-window"); + release_worker_promise.set_value(); + sink.waitForPendingExports(); + } + + EXPECT_TRUE(fs::exists( + gpufl::windowMetadataPath(sessionDir(), "device", 1))); + EXPECT_TRUE(fs::exists(tmpDir() / "device.1.log.gz")); +} + +TEST_F(FileLogSinkRotationTest, + ExistingMetadataWithDifferentPayloadRefusesSequenceReuse) { + const fs::path staged = tmpDir() / "device.1.log"; + writeText(staged, "first-payload"); + ASSERT_TRUE(gpufl::ensureWindowMetadata( + sessionDir(), "s1", "device", 1, staged)); + + writeText(staged, "different-payload"); + gpufl::LogFileRotator rotator(rotatorOptions(), nullptr); + EXPECT_EQ( + rotator.exportRetiredWindow(1, nullptr), + gpufl::LogFileRotator::ExportWindowResult::StagedForSalvage); + EXPECT_FALSE(fs::exists(sessionDir() / "device.1.log")) + << "an immutable identity must never be rebound to different bytes"; + EXPECT_TRUE(fs::exists(staged)); +} + +TEST_F(FileLogSinkRotationTest, + MetadataTombstonePreventsSequenceReuseAfterPayloadDeletion) { + { + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); + sink.write(gpufl::Channel::Device, R"({"event":1})"); + } + ASSERT_TRUE(fs::exists( + gpufl::windowMetadataPath(sessionDir(), "device", 1))); + ASSERT_TRUE(fs::remove(sessionDir() / "device.1.log.gz")); + + gpufl::GzipFileCompressor compressor; + gpufl::LogFileRotator rotator(rotatorOptions(), &compressor); + EXPECT_EQ(rotator.nextWindowIndex(), 2u) + << "ACK cleanup may delete the payload, but its metadata tombstone " + "must keep the sequence consumed."; +} + // Wiring: the collector beat calls Logger::rotateDueWindows(), which must // reach every sink exactly once. (Monitor's 250 ms beat → Logger is closed // by the 3090 sparse-channel run.) From e3c038fd14c48f2113d648e15c8b6e9e2b396b0c Mon Sep 17 00:00:00 2001 From: Myoungho Shin Date: Wed, 29 Jul 2026 10:03:38 -0700 Subject: [PATCH 3/5] fix(logger): retain windows until backend acknowledgement --- include/gpufl/core/logger/log_rotator.cpp | 18 ++++-------------- include/gpufl/core/logger/log_rotator.hpp | 7 ++++--- tests/core/test_file_log_sink_rotation.cpp | 20 ++++++++++---------- 3 files changed, 18 insertions(+), 27 deletions(-) diff --git a/include/gpufl/core/logger/log_rotator.cpp b/include/gpufl/core/logger/log_rotator.cpp index 6592319..05e58ad 100644 --- a/include/gpufl/core/logger/log_rotator.cpp +++ b/include/gpufl/core/logger/log_rotator.cpp @@ -107,22 +107,14 @@ LogFileRotator::RetireResult LogFileRotator::retireActiveWindow( LogFileRotator::ExportWindowResult LogFileRotator::exportRetiredWindow( const std::size_t index, std::size_t* pruned_windows, const WindowTiming& timing) const { + // Compatibility-only out parameter. Published payload retention is no + // longer inferred from a local file-count cap: the agent deletes a + // payload only after the backend ACKs its immutable window identity. + (void)pruned_windows; const std::string retired = retiredPath(index); std::error_code ec; if (!fs::exists(retired, ec)) return ExportWindowResult::NoData; - const auto prune = [&]() { - const std::size_t removed = pruneLogWindows( - fs::path(sessionDir()), opt_.channel_name, opt_.max_files); - if (removed > 0) { - if (pruned_windows) *pruned_windows += removed; - GFL_LOG_ERROR("[Logger] window cap (max_files=", opt_.max_files, - ") deleted ", removed, " old '", opt_.channel_name, - "' window(s) that may not have been uploaded yet. " - "Raise max_files or drain windows faster."); - } - }; - if (!compressor_) { const std::string published = rotatedPath(index); // Identity must become visible BEFORE the payload. The agent polls @@ -140,7 +132,6 @@ LogFileRotator::ExportWindowResult LogFileRotator::exportRetiredWindow( // tombstone and must match this same staged payload. return ExportWindowResult::StagedForSalvage; } - prune(); return ExportWindowResult::Published; } @@ -200,7 +191,6 @@ LogFileRotator::ExportWindowResult LogFileRotator::exportRetiredWindow( if (!publishWithRetry_(staging, published)) { return ExportWindowResult::StagedForSalvage; } - prune(); return ExportWindowResult::Published; } diff --git a/include/gpufl/core/logger/log_rotator.hpp b/include/gpufl/core/logger/log_rotator.hpp index 8744773..8425330 100644 --- a/include/gpufl/core/logger/log_rotator.hpp +++ b/include/gpufl/core/logger/log_rotator.hpp @@ -74,9 +74,10 @@ class LogFileRotator { * truncate the raw authority, then publish. This is the same crash-safe * transaction used by the asynchronous mid-run path. * - * `pruned_windows` (optional out): how many OLD published windows the - * max_files cap deleted while publishing this one - un-uploaded data - * loss the caller must surface, not swallow. + * `pruned_windows` is retained as a compatibility out-parameter and is + * left unchanged. Published payload deletion belongs to the agent after + * a durable backend ACK; the writer must never infer delivery from a + * local file-count limit. * * SYNCHRONOUS - compression and publish retries happen on the calling * thread. Used by the shutdown path only. Mid-run rotation splits this diff --git a/tests/core/test_file_log_sink_rotation.cpp b/tests/core/test_file_log_sink_rotation.cpp index 6429b09..23ab6ac 100644 --- a/tests/core/test_file_log_sink_rotation.cpp +++ b/tests/core/test_file_log_sink_rotation.cpp @@ -786,11 +786,11 @@ TEST_F(FileLogSinkRotationTest, CloseDrainsPendingExports) { EXPECT_FALSE(fs::exists(tmpDir())); } -// The max_files cap deletes the OLDEST published windows regardless of -// whether anything uploaded them - that is potential data loss and must be -// counted, never silent. (10 s cadence at the default cap of 100 is only -// ~17 min of agent outage tolerance.) -TEST_F(FileLogSinkRotationTest, PruneOnPublishIsCountedAsDataLoss) { +// The writer cannot know whether the backend durably accepted a window. +// Even a deliberately tiny legacy max_files setting must not delete data; +// the agent removes ACKed payloads and leaves metadata tombstones. +TEST_F(FileLogSinkRotationTest, + ClientNeverPrunesPublishedWindowsBeforeAgentAck) { gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000, /*rotate_bytes=*/0, /*max_files=*/2)); @@ -799,13 +799,13 @@ TEST_F(FileLogSinkRotationTest, PruneOnPublishIsCountedAsDataLoss) { sink.write(gpufl::Channel::Device, R"({"w":1})"); fake_now_ms_ += 5000; sink.rotateDueWindows(); - sink.waitForPendingExports(); + sink.waitForPendingExports(); } - // Three windows published, cap 2: the oldest was pruned. - EXPECT_EQ(publishedWindows("device"), 2u); + EXPECT_EQ(publishedWindows("device"), 3u); EXPECT_EQ(sink.rotationStats().by_time, 3u); - EXPECT_EQ(sink.rotationStats().pruned_windows, 1u); - EXPECT_FALSE(fs::exists(sessionDir() / "device.1.log.gz")); + EXPECT_EQ(sink.rotationStats().pruned_windows, 0u); + EXPECT_TRUE(fs::exists(sessionDir() / "device.1.log.gz")); + EXPECT_TRUE(fs::exists(sessionDir() / "device.2.log.gz")); EXPECT_TRUE(fs::exists(sessionDir() / "device.3.log.gz")); } From 37fa31ac54ddd44e1808634618aa75b7fea57e03 Mon Sep 17 00:00:00 2001 From: Myoungho Shin Date: Wed, 29 Jul 2026 10:36:53 -0700 Subject: [PATCH 4/5] fix(logger): stop capture when transport spool saturates --- include/gpufl/core/env_vars.hpp | 7 + include/gpufl/core/gpufl.cpp | 8 + include/gpufl/core/logger/file_log_sink.cpp | 173 +++++++++++++++++--- include/gpufl/core/logger/file_log_sink.hpp | 37 ++++- include/gpufl/core/logger/log_rotator.cpp | 23 +-- include/gpufl/core/logger/log_rotator.hpp | 14 +- include/gpufl/core/logger/log_salvage.cpp | 60 ++----- include/gpufl/core/logger/log_salvage.hpp | 24 +-- include/gpufl/core/logger/logger.hpp | 21 ++- tests/core/test_file_log_sink_rotation.cpp | 74 ++++++--- 10 files changed, 306 insertions(+), 135 deletions(-) diff --git a/include/gpufl/core/env_vars.hpp b/include/gpufl/core/env_vars.hpp index b1c1380..3aaf644 100644 --- a/include/gpufl/core/env_vars.hpp +++ b/include/gpufl/core/env_vars.hpp @@ -89,6 +89,13 @@ constexpr const char* kLogRotateBytes = "GPUFL_LOG_ROTATE_BYTES"; // ships each finished window mid-run. An empty window is never rotated. constexpr const char* kLogRotateAfterMs = "GPUFL_LOG_ROTATE_AFTER_MS"; +// Hard safety limits for the per-session transport spool. Once either limit +// is reached, GPUFlight stops accepting new profiling events and writes a +// durable transport-loss marker instead of filling the application's disk. +// The marker prevents a later uploader from reporting the session complete. +constexpr const char* kLogMaxSpoolBytes = "GPUFL_LOG_MAX_SPOOL_BYTES"; +constexpr const char* kLogMinFreeBytes = "GPUFL_LOG_MIN_FREE_BYTES"; + // Opt-in ("1", "true", "yes", "on"): flush each log line immediately. // Useful when diagnosing whether missing records are buffered in userspace. constexpr const char* kFlushLogsAlways = "GPUFL_FLUSH_LOGS_ALWAYS"; diff --git a/include/gpufl/core/gpufl.cpp b/include/gpufl/core/gpufl.cpp index 393e25c..ee8311b 100644 --- a/include/gpufl/core/gpufl.cpp +++ b/include/gpufl/core/gpufl.cpp @@ -336,6 +336,14 @@ bool init(const InitOptions& opts) { logOpts.rotate_after_ms = static_cast(ms); } } + if (const char* v = std::getenv(env::kLogMaxSpoolBytes)) { + logOpts.max_spool_bytes = + static_cast(std::strtoull(v, nullptr, 10)); + } + if (const char* v = std::getenv(env::kLogMinFreeBytes)) { + logOpts.min_free_bytes = + static_cast(std::strtoull(v, nullptr, 10)); + } g_lastLogPath = logPath; g_lastSessionId = rt->session_id; diff --git a/include/gpufl/core/logger/file_log_sink.cpp b/include/gpufl/core/logger/file_log_sink.cpp index 74b9304..768b761 100644 --- a/include/gpufl/core/logger/file_log_sink.cpp +++ b/include/gpufl/core/logger/file_log_sink.cpp @@ -3,6 +3,8 @@ #include #include #include +#include +#include #include "gpufl/core/debug_logger.hpp" #include "gpufl/core/logger/file_compressor.hpp" @@ -25,7 +27,6 @@ FileLogSink::FileChannel::FileChannel(std::string name, Logger::Options opt, r.base_path = opt_.base_path; r.session_id = opt_.session_id; r.channel_name = name_; - r.max_files = opt_.max_files; r.compress_rotated = opt_.compress_rotated; rotator_ = std::make_unique(r, compressor_.get()); @@ -90,6 +91,11 @@ void FileLogSink::FileChannel::closeLocked() { bool FileLogSink::FileChannel::isOpen() const { return opened_; } +std::uint64_t FileLogSink::FileChannel::currentBytes() const { + std::lock_guard lk(mu_); + return static_cast(current_bytes_); +} + void FileLogSink::FileChannel::ensureOpenLocked() { if (!opened_) return; if (stream_.is_open()) return; @@ -204,19 +210,16 @@ void FileLogSink::FileChannel::exportRetired( const std::size_t index, const WindowTiming timing) { if (opt_.before_retired_export) opt_.before_retired_export(); const auto started = std::chrono::steady_clock::now(); - std::size_t pruned = 0; // No channel lock held: the retired file is immutable and nothing // writes to it any more, so gzip and the publish backoff cost this // worker thread only. - const auto result = - rotator_->exportRetiredWindow(index, &pruned, timing); + const auto result = rotator_->exportRetiredWindow(index, timing); const auto elapsed_ms = std::chrono::duration_cast( std::chrono::steady_clock::now() - started) .count(); std::lock_guard lk(mu_); - rotation_stats_.pruned_windows += pruned; if (elapsed_ms > rotation_stats_.max_export_ms) { rotation_stats_.max_export_ms = elapsed_ms; } @@ -250,16 +253,16 @@ void FileLogSink::FileChannel::rotateIfDue() { rotateLocked(RotateTrigger::Time); } -void FileLogSink::FileChannel::write(std::string_view line) { +bool FileLogSink::FileChannel::write(std::string_view line) { std::lock_guard lk(mu_); if (!opened_) { GFL_LOG_ERROR("Write failed: Channel '", name_, "' is not opened"); - return; + return false; } ensureOpenLocked(); if (!stream_.good()) { GFL_LOG_ERROR("Write failed: Stream bad for '", name_, "'"); - return; + return false; } const size_t bytesToWrite = line.size() + 1; // Two rotation triggers, whichever is due first. Time is evaluated @@ -281,7 +284,7 @@ void FileLogSink::FileChannel::write(std::string_view line) { rotateLocked(time_due ? RotateTrigger::Time : RotateTrigger::Size); if (!stream_.good()) { GFL_LOG_ERROR("Write failed after rotate for '", name_, "'"); - return; + return false; } } // Write line + newline. Per-write flush is gated behind @@ -312,6 +315,7 @@ void FileLogSink::FileChannel::write(std::string_view line) { window_first_write_ms_ = now; } current_bytes_ += bytesToWrite; + return true; } FileLogSink::RotationStats FileLogSink::FileChannel::rotationStats() const { @@ -328,8 +332,11 @@ FileLogSink::FileLogSink(const Logger::Options& opt) { "ownership."); return; } - const fs::path session_dir = - fs::path(opt.base_path) / opt.session_id; + const fs::path session_dir = fs::path(opt.base_path) / opt.session_id; + session_dir_ = session_dir; + max_spool_bytes_ = opt.max_spool_bytes; + min_free_bytes_ = opt.min_free_bytes; + spool_now_ms_ = opt.now_ms; std::string lock_error; session_ownership_ = SessionOwnershipLock::tryAcquire(session_dir, &lock_error); @@ -348,6 +355,8 @@ FileLogSink::FileLogSink(const Logger::Options& opt) { r.base_path = opt.base_path; r.session_id = opt.session_id; temp_dir_ = LogFileRotator(r, nullptr).tempDir(); + spool_estimated_bytes_.store( + spoolBytesOnDisk(), std::memory_order_relaxed); } FileLogSink::~FileLogSink() { close(); } @@ -372,7 +381,6 @@ FileLogSink::RotationStats FileLogSink::rotationStats() const { total.published += s.published; total.staged += s.staged; total.export_failed += s.export_failed; - total.pruned_windows += s.pruned_windows; total.max_export_ms = std::max(total.max_export_ms, s.max_export_ms); } @@ -384,10 +392,116 @@ FileLogSink::RotationStats FileLogSink::rotationStats() const { total.max_pending_export_bytes = max_pending_export_bytes_; total.lost_windows = lost_windows_; } + total.spool_saturated = + spool_saturated_.load(std::memory_order_acquire); + total.spool_bytes_at_saturation = + spool_bytes_at_saturation_.load(std::memory_order_relaxed); + total.dropped_events = + dropped_events_.load(std::memory_order_relaxed); + total.dropped_bytes = + dropped_bytes_.load(std::memory_order_relaxed); return total; } +std::uint64_t FileLogSink::spoolBytesOnDisk() const { + std::uint64_t total = 0; + std::error_code ec; + if (session_dir_.empty() || !fs::exists(session_dir_, ec)) return 0; + fs::recursive_directory_iterator it( + session_dir_, fs::directory_options::skip_permission_denied, ec); + const fs::recursive_directory_iterator end; + while (!ec && it != end) { + std::error_code entry_ec; + if (it->is_regular_file(entry_ec)) { + const fs::path path = it->path(); + const bool active_channel = + path.parent_path().filename() == ".tmp" && + (path.filename() == "device.log" || + path.filename() == "scope.log" || + path.filename() == "system.log" || + path.filename() == "sass.log"); + if (!active_channel) { + const auto bytes = it->file_size(entry_ec); + if (!entry_ec) total += static_cast(bytes); + } + } + it.increment(ec); + } + for (const FileChannel* ch : + {chanDevice_.get(), chanScope_.get(), chanSystem_.get(), + chanSass_.get()}) { + if (ch) total += ch->currentBytes(); + } + return total; +} + +void FileLogSink::markSpoolSaturated( + const std::uint64_t spool_bytes, + const std::uint64_t available_bytes, + const char* reason) { + if (spool_saturated_.exchange(true, std::memory_order_acq_rel)) return; + spool_bytes_at_saturation_.store( + spool_bytes, std::memory_order_relaxed); + + std::ostringstream detail; + detail << reason << ":spool_bytes=" << spool_bytes + << ",max_spool_bytes=" << max_spool_bytes_ + << ",available_bytes=" << available_bytes + << ",min_free_bytes=" << min_free_bytes_; + const bool marker_written = recordTransportLossMarker( + session_dir_, "spool", 0, detail.str()); + GFL_LOG_ERROR( + "[Logger] transport spool saturated for session '", + session_dir_.string(), "' (", detail.str(), + "). GPUFlight stopped accepting new profiling events to protect " + "the target application's filesystem. The profile is incomplete.", + marker_written + ? " A durable transport-loss marker was written." + : " WARNING: the durable loss marker could not be written."); +} + +std::int64_t FileLogSink::spoolNowMs() const { + if (spool_now_ms_) return spool_now_ms_(); + return std::chrono::duration_cast( + std::chrono::steady_clock::now().time_since_epoch()) + .count(); +} + +void FileLogSink::checkSpoolBudget(const bool force) { + if (spool_saturated_.load(std::memory_order_acquire) || + (max_spool_bytes_ == 0 && min_free_bytes_ == 0)) { + return; + } + std::lock_guard lk(spool_budget_mu_); + if (spool_saturated_.load(std::memory_order_relaxed)) return; + const std::int64_t now = spoolNowMs(); + // Directory scans are intentionally not on the 250 ms collector cadence. + // One scan per second reconciles agent-side ACK deletions and filesystem + // free space; the cheap write-byte estimate forces an immediate scan when + // this process approaches its session limit. + if (!force && last_spool_check_ms_ >= 0 && + now - last_spool_check_ms_ < 1000) { + return; + } + last_spool_check_ms_ = now; + + const std::uint64_t spool_bytes = spoolBytesOnDisk(); + spool_estimated_bytes_.store(spool_bytes, std::memory_order_relaxed); + std::error_code space_ec; + const auto space = fs::space(session_dir_, space_ec); + const std::uint64_t available = + space_ec ? std::numeric_limits::max() + : static_cast(space.available); + if (max_spool_bytes_ > 0 && spool_bytes >= max_spool_bytes_) { + markSpoolSaturated(spool_bytes, available, "spool_budget_exceeded"); + } else if (min_free_bytes_ > 0 && !space_ec && + available <= min_free_bytes_) { + markSpoolSaturated(spool_bytes, available, "filesystem_reserve_reached"); + } +} + void FileLogSink::rotateDueWindows() { + checkSpoolBudget(); for (FileChannel* ch : {chanDevice_.get(), chanScope_.get(), chanSystem_.get(), chanSass_.get()}) { if (ch) ch->rotateIfDue(); @@ -501,9 +615,9 @@ void FileLogSink::close() { lost_windows_ += static_cast(salvage.lost_windows); GFL_LOG_ERROR("[Logger] session '", session_dir.string(), "': ", salvage.lost_windows, - " transport window(s) were unrecoverable and have " - "been discarded. Their events are LOST - the " - "uploaded session is incomplete."); + " durable transport-loss marker(s) are present. " + "Some profiling events are LOST and the uploaded " + "session must remain incomplete."); } if (salvage.deferred > 0 || sessionTempDirHasDeferredData(session_dir)) { GFL_LOG_ERROR("[Logger] session temp dir '", temp_dir_, @@ -539,19 +653,38 @@ FileLogSink::FileChannel* FileLogSink::resolveChannel(Channel ch) const { } void FileLogSink::write(Channel ch, std::string_view json) { + if (spool_saturated_.load(std::memory_order_acquire)) { + dropped_events_.fetch_add(1, std::memory_order_relaxed); + dropped_bytes_.fetch_add( + static_cast(json.size() + 1), + std::memory_order_relaxed); + return; + } + std::uint64_t copies_written = 0; if (ch == Channel::All) { - if (chanDevice_) chanDevice_->write(json); - if (chanScope_) chanScope_->write(json); - if (chanSystem_) chanSystem_->write(json); + if (chanDevice_ && chanDevice_->write(json)) ++copies_written; + if (chanScope_ && chanScope_->write(json)) ++copies_written; + if (chanSystem_ && chanSystem_->write(json)) ++copies_written; // Sass is part of the fan-out so each sass.log is self-ordered: // dictionary_update lines land in the file BEFORE the // source_file_content/cubin_disassembly lines that reference their // IDs - live tailers (agent) read channels independently and have // no cross-file ordering. - if (chanSass_) chanSass_->write(json); + if (chanSass_ && chanSass_->write(json)) ++copies_written; } else { if (FileChannel* channel = resolveChannel(ch)) { - channel->write(json); + if (channel->write(json)) ++copies_written; + } + } + if (copies_written > 0) { + const std::uint64_t bytes = + copies_written * static_cast(json.size() + 1); + const std::uint64_t estimated = + spool_estimated_bytes_.fetch_add( + bytes, std::memory_order_relaxed) + + bytes; + if (max_spool_bytes_ > 0 && estimated >= max_spool_bytes_) { + checkSpoolBudget(/*force=*/true); } } } diff --git a/include/gpufl/core/logger/file_log_sink.hpp b/include/gpufl/core/logger/file_log_sink.hpp index 4061a68..671cb67 100644 --- a/include/gpufl/core/logger/file_log_sink.hpp +++ b/include/gpufl/core/logger/file_log_sink.hpp @@ -1,9 +1,11 @@ #pragma once +#include #include #include #include #include +#include #include #include #include @@ -69,8 +71,8 @@ class FileLogSink final : public ILogSink { * * by_size / by_time count durable CUTOVERS keyed by which trigger fired * first. published / staged / export_failed describe the later worker - * outcome; pruned_windows counts old published windows the max_files cap - * DELETED, i.e. potential un-uploaded data loss. + * outcome. Spool saturation is terminal: new events are dropped only + * after a durable marker makes the incomplete session visible. */ struct RotationStats { // Windows CUT OVER by each trigger. A cutover is the boundary @@ -86,14 +88,11 @@ class FileLogSink final : public ILogSink { std::size_t published = 0; // finished file in the session root std::size_t staged = 0; // compressed, publish blocked std::size_t export_failed = 0; // compression failed - // Old published windows the max_files cap DELETED - potential - // un-uploaded data loss, surfaced rather than swallowed. - std::size_t pruned_windows = 0; // Slowest single export, for sizing the compression cost that the // worker now absorbs instead of the collector. std::int64_t max_export_ms = 0; - // Retirement-worker backlog. Unlike max_files (published windows), - // these cover immutable raw windows still waiting for gzip/publish. + // Retirement-worker backlog: immutable raw windows still waiting for + // gzip/publish. std::size_t pending_exports = 0; std::size_t max_pending_exports = 0; std::uint64_t pending_export_bytes = 0; @@ -102,6 +101,10 @@ class FileLogSink final : public ILogSink { // nothing on disk could still yield them. Terminal, unlike // `staged`/`export_failed`, which salvage still recovers. std::size_t lost_windows = 0; + bool spool_saturated = false; + std::uint64_t spool_bytes_at_saturation = 0; + std::uint64_t dropped_events = 0; + std::uint64_t dropped_bytes = 0; }; RotationStats rotationStats() const; @@ -130,9 +133,10 @@ class FileLogSink final : public ILogSink { FileChannel(std::string name, Logger::Options opt, FileLogSink* owner); ~FileChannel(); - void write(std::string_view line); + bool write(std::string_view line); void close(); bool isOpen() const; + std::uint64_t currentBytes() const; RotationStats rotationStats() const; void rotateIfDue(); /** @@ -188,6 +192,12 @@ class FileLogSink final : public ILogSink { void enqueueRetired(FileChannel* channel, std::size_t index, std::uint64_t bytes, WindowTiming timing); void stopRetirementWorker(); + void checkSpoolBudget(bool force = false); + void markSpoolSaturated(std::uint64_t spool_bytes, + std::uint64_t available_bytes, + const char* reason); + std::uint64_t spoolBytesOnDisk() const; + std::int64_t spoolNowMs() const; std::unique_ptr chanDevice_; std::unique_ptr chanScope_; @@ -200,6 +210,17 @@ class FileLogSink final : public ILogSink { // The shared session `.tmp` dir, removed once in close() after every // channel has finalized (its own actives would block earlier removal). std::string temp_dir_; + std::filesystem::path session_dir_; + std::uint64_t max_spool_bytes_ = 0; + std::uint64_t min_free_bytes_ = 0; + std::function spool_now_ms_; + mutable std::mutex spool_budget_mu_; + std::int64_t last_spool_check_ms_ = -1; + std::atomic spool_estimated_bytes_{0}; + std::atomic spool_saturated_{false}; + std::atomic spool_bytes_at_saturation_{0}; + std::atomic dropped_events_{0}; + std::atomic dropped_bytes_{0}; // Retirement queue: cutover happens on whichever thread hit the // boundary (fast, metadata-only), compression and publish retries diff --git a/include/gpufl/core/logger/log_rotator.cpp b/include/gpufl/core/logger/log_rotator.cpp index 05e58ad..9e2fbcc 100644 --- a/include/gpufl/core/logger/log_rotator.cpp +++ b/include/gpufl/core/logger/log_rotator.cpp @@ -105,12 +105,7 @@ LogFileRotator::RetireResult LogFileRotator::retireActiveWindow( } LogFileRotator::ExportWindowResult LogFileRotator::exportRetiredWindow( - const std::size_t index, std::size_t* pruned_windows, - const WindowTiming& timing) const { - // Compatibility-only out parameter. Published payload retention is no - // longer inferred from a local file-count cap: the agent deletes a - // payload only after the backend ACKs its immutable window identity. - (void)pruned_windows; + const std::size_t index, const WindowTiming& timing) const { const std::string retired = retiredPath(index); std::error_code ec; if (!fs::exists(retired, ec)) return ExportWindowResult::NoData; @@ -194,13 +189,12 @@ LogFileRotator::ExportWindowResult LogFileRotator::exportRetiredWindow( return ExportWindowResult::Published; } -LogFileRotator::ExportWindowResult LogFileRotator::exportWindow_( - std::size_t* pruned_windows) const { - return exportWindowAt_(nextWindowIndex(), pruned_windows); +LogFileRotator::ExportWindowResult LogFileRotator::exportWindow_() const { + return exportWindowAt_(nextWindowIndex()); } LogFileRotator::ExportWindowResult LogFileRotator::exportWindowAt_( - const std::size_t index, std::size_t* pruned_windows) const { + const std::size_t index) const { switch (retireActiveWindow(index)) { case RetireResult::NoData: return ExportWindowResult::NoData; @@ -209,14 +203,13 @@ LogFileRotator::ExportWindowResult LogFileRotator::exportWindowAt_( case RetireResult::Retired: // Shutdown uses the same crash-safe raw -> .part -> completed // gzip transaction as mid-run retirement; only the thread differs. - return exportRetiredWindow(index, pruned_windows); + return exportRetiredWindow(index); } return ExportWindowResult::DeferredInActive; } -LogFileRotator::ExportWindowResult LogFileRotator::rotate( - std::size_t* pruned_windows) const { - return exportWindow_(pruned_windows); +LogFileRotator::ExportWindowResult LogFileRotator::rotate() const { + return exportWindow_(); } LogFileRotator::ExportWindowResult LogFileRotator::compressActive( @@ -231,7 +224,7 @@ LogFileRotator::ExportWindowResult LogFileRotator::compressActive( result = ExportWindowResult::DeferredInActive; break; case RetireResult::Retired: - result = exportRetiredWindow(index, nullptr, timing); + result = exportRetiredWindow(index, timing); break; } // Best-effort removal of this channel's (now exported) active file. diff --git a/include/gpufl/core/logger/log_rotator.hpp b/include/gpufl/core/logger/log_rotator.hpp index 8425330..38dee47 100644 --- a/include/gpufl/core/logger/log_rotator.hpp +++ b/include/gpufl/core/logger/log_rotator.hpp @@ -25,7 +25,6 @@ struct LogRotationOptions { */ std::string session_id; std::string channel_name; - std::size_t max_files = 100; bool compress_rotated = true; }; @@ -74,17 +73,12 @@ class LogFileRotator { * truncate the raw authority, then publish. This is the same crash-safe * transaction used by the asynchronous mid-run path. * - * `pruned_windows` is retained as a compatibility out-parameter and is - * left unchanged. Published payload deletion belongs to the agent after - * a durable backend ACK; the writer must never infer delivery from a - * local file-count limit. - * * SYNCHRONOUS - compression and publish retries happen on the calling * thread. Used by the shutdown path only. Mid-run rotation splits this * into retireActiveWindow() + exportRetiredWindow() so no collector or * writer thread ever waits on gzip. */ - ExportWindowResult rotate(std::size_t* pruned_windows = nullptr) const; + ExportWindowResult rotate() const; /** Next append-style window index for this channel (root + `.tmp`). */ [[nodiscard]] std::size_t nextWindowIndex() const; @@ -111,7 +105,6 @@ class LogFileRotator { * publish retry/backoff for transient holders lives here. */ ExportWindowResult exportRetiredWindow(std::size_t index, - std::size_t* pruned_windows, const WindowTiming& timing = {}) const; /** @@ -152,9 +145,8 @@ class LogFileRotator { const std::string& to) const; /** Shared body of rotate()/compressActive(). */ - ExportWindowResult exportWindow_(std::size_t* pruned_windows) const; - ExportWindowResult exportWindowAt_(std::size_t index, - std::size_t* pruned_windows) const; + ExportWindowResult exportWindow_() const; + ExportWindowResult exportWindowAt_(std::size_t index) const; LogRotationOptions opt_; IFileCompressor* compressor_ = nullptr; // non-owning diff --git a/include/gpufl/core/logger/log_salvage.cpp b/include/gpufl/core/logger/log_salvage.cpp index b782b81..e5fc211 100644 --- a/include/gpufl/core/logger/log_salvage.cpp +++ b/include/gpufl/core/logger/log_salvage.cpp @@ -95,28 +95,6 @@ void scanMaxIndex(const fs::path& dir, } } -std::vector publishedWindowIndices(const fs::path& session_dir, - const std::string& channel) { - std::set indices; - std::error_code ec; - if (!fs::exists(session_dir, ec) || !fs::is_directory(session_dir, ec)) { - return {}; - } - for (const auto& entry : fs::directory_iterator(session_dir, ec)) { - std::error_code e_ec; - if (!entry.is_regular_file(e_ec)) continue; - std::string ch; - std::size_t idx = 0; - bool compressed = false; - if (parseWindowName(entry.path().filename().string(), ch, idx, - compressed) && - ch == channel && idx > 0) { - indices.insert(idx); - } - } - return {indices.begin(), indices.end()}; -} - bool endsWith(const std::string& value, const std::string& suffix) { return value.size() >= suffix.size() && value.compare(value.size() - suffix.size(), suffix.size(), @@ -262,10 +240,10 @@ std::string jsonEscape(const std::string& value) { return escaped; } -bool recordTransportLoss(const fs::path& session_dir, - const std::string& channel, - const std::size_t index, - const std::string& reason) { +bool recordTransportLossImpl(const fs::path& session_dir, + const std::string& channel, + const std::size_t index, + const std::string& reason) { const fs::path marker = session_dir / (std::string(kTransportLossPrefix) + markerSafe(channel) + "." + @@ -430,6 +408,13 @@ std::size_t transportLossMarkerCount(const fs::path& session_dir) { return count; } +bool recordTransportLossMarker(const fs::path& session_dir, + const std::string& channel, + const std::size_t index, + const std::string& reason) { + return recordTransportLossImpl(session_dir, channel, index, reason); +} + std::size_t nextLogWindowIndex(const fs::path& session_dir, const std::string& channel) { // Scan `.tmp` FIRST, the session root SECOND - the reverse of the @@ -450,27 +435,6 @@ std::size_t nextLogWindowIndex(const fs::path& session_dir, return max_index + 1; } -std::size_t pruneLogWindows(const fs::path& session_dir, - const std::string& channel, - const std::size_t max_files) { - if (max_files == 0) return 0; - auto indices = publishedWindowIndices(session_dir, channel); - if (indices.size() <= max_files) return 0; - const std::size_t remove_count = indices.size() - max_files; - std::size_t removed = 0; - for (std::size_t i = 0; i < remove_count; ++i) { - const auto idx = indices[i]; - const fs::path base = - session_dir / (channel + "." + std::to_string(idx) + ".log"); - std::error_code ec; - const bool got_log = fs::remove(base, ec); - std::error_code gz_ec; - const bool got_gz = fs::remove(base.string() + ".gz", gz_ec); - if (got_log || got_gz) ++removed; - } - return removed; -} - LogSalvageResult salvageOwnedSessionTempDir(const fs::path& session_dir) { LogSalvageResult result; // A prior pass may already have discarded an unrecoverable artifact. @@ -580,7 +544,7 @@ LogSalvageResult salvageOwnedSessionTempDir(const fs::path& session_dir) { // Persist BEFORE deleting the last artifact. If the marker // cannot be made durable, leave the empty file deferred: an // unfinished session is preferable to invisible loss. - loss_recorded = recordTransportLoss( + loss_recorded = recordTransportLossImpl( session_dir, channel, idx, "empty_gzip_no_raw"); } if ((raw_recoverable || empty_artifact) && loss_recorded) { diff --git a/include/gpufl/core/logger/log_salvage.hpp b/include/gpufl/core/logger/log_salvage.hpp index 6e8c1a0..140aa5d 100644 --- a/include/gpufl/core/logger/log_salvage.hpp +++ b/include/gpufl/core/logger/log_salvage.hpp @@ -75,6 +75,19 @@ bool isValidGzipFile(const std::filesystem::path& path); std::size_t transportLossMarkerCount( const std::filesystem::path& session_dir); +/** + * Persist one idempotent terminal-loss marker outside `.tmp`. + * + * `channel` may be a transport channel or a session-level category such as + * "spool". A marker prevents upload from reporting a partial session as + * complete. + */ +bool recordTransportLossMarker( + const std::filesystem::path& session_dir, + const std::string& channel, + std::size_t index, + const std::string& reason); + /** * Return the next append-style window index for `channel` in a session. * Both published root files and unpublished `.tmp` staging files count, so @@ -83,17 +96,6 @@ std::size_t transportLossMarkerCount( std::size_t nextLogWindowIndex(const std::filesystem::path& session_dir, const std::string& channel); -/** - * Remove oldest published windows once more than `max_files` exist, and - * return how many were deleted. A nonzero return is DATA LOSS for any - * window the agent had not uploaded yet - callers surface it loudly - * (short rotation cadences reach the cap in minutes: 100 files at a 10 s - * cadence is ~17 min of agent/backend outage tolerance). - */ -std::size_t pruneLogWindows(const std::filesystem::path& session_dir, - const std::string& channel, - std::size_t max_files); - /** Publish staged `.tmp/*.log.gz` files and export non-empty `.tmp/*.log`. */ LogSalvageResult salvageSessionTempDir( const std::filesystem::path& session_dir); diff --git a/include/gpufl/core/logger/logger.hpp b/include/gpufl/core/logger/logger.hpp index dd9d147..f239c33 100644 --- a/include/gpufl/core/logger/logger.hpp +++ b/include/gpufl/core/logger/logger.hpp @@ -43,6 +43,14 @@ class Logger { * lockstep. */ static constexpr std::size_t kDefaultRotateBytes = 64 * 1024 * 1024; + // A profiler must not exhaust the filesystem used by the target + // application during a prolonged agent/backend outage. These are + // session-wide safety limits, not retention policy: acknowledged + // payload deletion still belongs exclusively to the agent. + static constexpr std::uint64_t kDefaultMaxSpoolBytes = + 4ull * 1024 * 1024 * 1024; + static constexpr std::uint64_t kDefaultMinFreeBytes = + 512ull * 1024 * 1024; struct Options { std::string base_path; @@ -98,7 +106,18 @@ class Logger { * prove the cutover caller has already returned. */ std::function before_retired_export; - std::size_t max_files = 100; + /** + * Stop accepting new profiling events once this session's on-disk + * spool reaches the limit. 0 disables the per-session byte limit. + * Saturation is terminal for the session and is recorded durably so + * upload cannot later claim the resulting partial profile is complete. + */ + std::uint64_t max_spool_bytes = kDefaultMaxSpoolBytes; + /** + * Also stop before the filesystem's available space drops below this + * reserve. 0 disables the free-space guard. + */ + std::uint64_t min_free_bytes = kDefaultMinFreeBytes; bool compress_rotated = true; bool flush_always = false; int system_sample_rate_ms = 0; diff --git a/tests/core/test_file_log_sink_rotation.cpp b/tests/core/test_file_log_sink_rotation.cpp index 23ab6ac..8172f9b 100644 --- a/tests/core/test_file_log_sink_rotation.cpp +++ b/tests/core/test_file_log_sink_rotation.cpp @@ -84,14 +84,12 @@ class FileLogSinkRotationTest : public ::testing::Test { } gpufl::Logger::Options options(std::int64_t rotate_after_ms, - std::size_t rotate_bytes = 0, - std::size_t max_files = 100) { + std::size_t rotate_bytes = 0) { gpufl::Logger::Options o; o.base_path = base_.string(); o.session_id = "s1"; o.rotate_bytes = rotate_bytes; // 0 = size trigger off o.rotate_after_ms = rotate_after_ms; - o.max_files = max_files; o.now_ms = [this] { return fake_now_ms_; }; return o; } @@ -133,7 +131,6 @@ class FileLogSinkRotationTest : public ::testing::Test { r.base_path = base_.string(); r.session_id = "s1"; r.channel_name = "device"; - r.max_files = 100; r.compress_rotated = true; return r; } @@ -613,8 +610,7 @@ TEST_F(FileLogSinkRotationTest, ExportRefusesToOverwriteAPublishedWindow) { writeText(sessionDir() / "device.1.log.gz", "the already-published window"); writeText(tmpDir() / "device.1.log", R"({"w":"second"})"); - std::size_t pruned = 0; - const auto result = rotator.exportRetiredWindow(1, &pruned); + const auto result = rotator.exportRetiredWindow(1); EXPECT_EQ(result, gpufl::LogFileRotator::ExportWindowResult::StagedForSalvage); @@ -640,8 +636,7 @@ TEST_F(FileLogSinkRotationTest, fs::remove(published_raw); gpufl::LogFileRotator rotator(rotatorOptions(), &compressor); - std::size_t pruned = 0; - ASSERT_EQ(rotator.exportRetiredWindow(1, &pruned), + ASSERT_EQ(rotator.exportRetiredWindow(1), gpufl::LogFileRotator::ExportWindowResult::StagedForSalvage); ASSERT_TRUE(fs::exists(tmpDir() / "device.1.log.gz")); @@ -718,8 +713,7 @@ TEST_F(FileLogSinkRotationTest, ExportOnlyEverCompressesToAPartFile) { gpufl::LogFileRotator rotator(rotatorOptions(), &compressor); writeText(tmpDir() / "device.1.log", R"({"window":1})"); - std::size_t pruned = 0; - const auto result = rotator.exportRetiredWindow(1, &pruned); + const auto result = rotator.exportRetiredWindow(1); EXPECT_EQ(result, gpufl::LogFileRotator::ExportWindowResult::Published); ASSERT_EQ(compressor.targets.size(), 1u); @@ -740,8 +734,7 @@ TEST_F(FileLogSinkRotationTest, FailedCompressionLeavesNoCompletedGzip) { const std::string payload = R"({"window":1})"; writeText(tmpDir() / "device.1.log", payload); - std::size_t pruned = 0; - const auto result = rotator.exportRetiredWindow(1, &pruned); + const auto result = rotator.exportRetiredWindow(1); EXPECT_EQ(result, gpufl::LogFileRotator::ExportWindowResult::DeferredInActive); @@ -762,8 +755,7 @@ TEST_F(FileLogSinkRotationTest, ExportRefusesToPublishWhileTheRawSurvives) { fs::create_directories(tmpDir() / "device.1.log" / "holder"); writeText(tmpDir() / "device.1.log" / "holder" / "pin", "x"); - std::size_t pruned = 0; - const auto result = rotator.exportRetiredWindow(1, &pruned); + const auto result = rotator.exportRetiredWindow(1); EXPECT_EQ(result, gpufl::LogFileRotator::ExportWindowResult::StagedForSalvage); @@ -787,13 +779,11 @@ TEST_F(FileLogSinkRotationTest, CloseDrainsPendingExports) { } // The writer cannot know whether the backend durably accepted a window. -// Even a deliberately tiny legacy max_files setting must not delete data; -// the agent removes ACKed payloads and leaves metadata tombstones. +// It never deletes published data; the agent removes ACKed payloads and +// leaves metadata tombstones. TEST_F(FileLogSinkRotationTest, ClientNeverPrunesPublishedWindowsBeforeAgentAck) { - gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000, - /*rotate_bytes=*/0, - /*max_files=*/2)); + gpufl::FileLogSink sink(options(/*rotate_after_ms=*/5000)); for (int i = 1; i <= 3; ++i) { sink.write(gpufl::Channel::Device, R"({"w":1})"); @@ -803,12 +793,54 @@ TEST_F(FileLogSinkRotationTest, } EXPECT_EQ(publishedWindows("device"), 3u); EXPECT_EQ(sink.rotationStats().by_time, 3u); - EXPECT_EQ(sink.rotationStats().pruned_windows, 0u); EXPECT_TRUE(fs::exists(sessionDir() / "device.1.log.gz")); EXPECT_TRUE(fs::exists(sessionDir() / "device.2.log.gz")); EXPECT_TRUE(fs::exists(sessionDir() / "device.3.log.gz")); } +TEST_F(FileLogSinkRotationTest, + SpoolBudgetStopsNewWritesAndPersistsTerminalLoss) { + auto opt = options(/*rotate_after_ms=*/0); + opt.flush_always = true; + opt.max_spool_bytes = 32; + opt.min_free_bytes = 0; + gpufl::FileLogSink sink(opt); + + sink.write(gpufl::Channel::Device, std::string(64, 'x')); + sink.rotateDueWindows(); // collector beat performs the disk check + + const auto saturated = sink.rotationStats(); + ASSERT_TRUE(saturated.spool_saturated); + EXPECT_GE(saturated.spool_bytes_at_saturation, 32u); + EXPECT_EQ(gpufl::transportLossMarkerCount(sessionDir()), 1u); + + const auto bytes_before = + fs::file_size(tmpDir() / "device.log"); + sink.write(gpufl::Channel::Device, R"({"must":"drop"})"); + EXPECT_EQ(fs::file_size(tmpDir() / "device.log"), bytes_before); + EXPECT_EQ(sink.rotationStats().dropped_events, 1u); + EXPECT_GT(sink.rotationStats().dropped_bytes, 0u); + + sink.close(); + EXPECT_EQ(gpufl::transportLossMarkerCount(sessionDir()), 1u) + << "clean shutdown must not erase the durable incomplete-session " + "signal"; +} + +TEST_F(FileLogSinkRotationTest, ZeroSpoolLimitsExplicitlyDisableTheGuard) { + auto opt = options(/*rotate_after_ms=*/0); + opt.flush_always = true; + opt.max_spool_bytes = 0; + opt.min_free_bytes = 0; + gpufl::FileLogSink sink(opt); + + sink.write(gpufl::Channel::Device, std::string(64, 'x')); + sink.rotateDueWindows(); + + EXPECT_FALSE(sink.rotationStats().spool_saturated); + EXPECT_EQ(gpufl::transportLossMarkerCount(sessionDir()), 0u); +} + TEST_F(FileLogSinkRotationTest, SessionOwnershipIsExclusiveAndCrashReleased) { std::string first_error; auto first = @@ -949,7 +981,7 @@ TEST_F(FileLogSinkRotationTest, writeText(staged, "different-payload"); gpufl::LogFileRotator rotator(rotatorOptions(), nullptr); EXPECT_EQ( - rotator.exportRetiredWindow(1, nullptr), + rotator.exportRetiredWindow(1), gpufl::LogFileRotator::ExportWindowResult::StagedForSalvage); EXPECT_FALSE(fs::exists(sessionDir() / "device.1.log")) << "an immutable identity must never be rebound to different bytes"; From e2299ce1854be98b8f4c51b48cc0729df727bfb4 Mon Sep 17 00:00:00 2001 From: Myoungho Shin Date: Wed, 29 Jul 2026 11:23:17 -0700 Subject: [PATCH 5/5] fix(logger): preflight filesystem spool limits --- include/gpufl/core/logger/file_log_sink.cpp | 75 +++++++++++++++++++-- include/gpufl/core/logger/file_log_sink.hpp | 9 ++- tests/core/test_file_log_sink_rotation.cpp | 52 +++++++++++++- 3 files changed, 128 insertions(+), 8 deletions(-) diff --git a/include/gpufl/core/logger/file_log_sink.cpp b/include/gpufl/core/logger/file_log_sink.cpp index 768b761..39a9f5a 100644 --- a/include/gpufl/core/logger/file_log_sink.cpp +++ b/include/gpufl/core/logger/file_log_sink.cpp @@ -357,6 +357,10 @@ FileLogSink::FileLogSink(const Logger::Options& opt) { temp_dir_ = LogFileRotator(r, nullptr).tempDir(); spool_estimated_bytes_.store( spoolBytesOnDisk(), std::memory_order_relaxed); + // Establish the real filesystem reserve before the first profiling event. + // Waiting for the collector beat lets a large first event fill an already + // constrained filesystem before the guard ever runs. + checkSpoolBudget(/*force=*/true); } FileLogSink::~FileLogSink() { close(); } @@ -467,7 +471,8 @@ std::int64_t FileLogSink::spoolNowMs() const { .count(); } -void FileLogSink::checkSpoolBudget(const bool force) { +void FileLogSink::checkSpoolBudget( + const bool force, const std::uint64_t incoming_bytes) { if (spool_saturated_.load(std::memory_order_acquire) || (max_spool_bytes_ == 0 && min_free_bytes_ == 0)) { return; @@ -492,10 +497,24 @@ void FileLogSink::checkSpoolBudget(const bool force) { const std::uint64_t available = space_ec ? std::numeric_limits::max() : static_cast(space.available); - if (max_spool_bytes_ > 0 && spool_bytes >= max_spool_bytes_) { - markSpoolSaturated(spool_bytes, available, "spool_budget_exceeded"); + available_bytes_estimate_.store(available, std::memory_order_relaxed); + const auto reaches = [](const std::uint64_t current, + const std::uint64_t added, + const std::uint64_t limit) { + return current >= limit || added >= limit - current; + }; + if (max_spool_bytes_ > 0 && + reaches(spool_bytes, incoming_bytes, max_spool_bytes_)) { + const std::uint64_t projected = + incoming_bytes > + std::numeric_limits::max() - spool_bytes + ? std::numeric_limits::max() + : spool_bytes + incoming_bytes; + markSpoolSaturated( + projected, available, "spool_budget_exceeded"); } else if (min_free_bytes_ > 0 && !space_ec && - available <= min_free_bytes_) { + (available <= min_free_bytes_ || + incoming_bytes >= available - min_free_bytes_)) { markSpoolSaturated(spool_bytes, available, "filesystem_reserve_reached"); } } @@ -660,6 +679,43 @@ void FileLogSink::write(Channel ch, std::string_view json) { std::memory_order_relaxed); return; } + const std::uint64_t planned_copies = + ch == Channel::All + ? static_cast( + (chanDevice_ ? 1 : 0) + (chanScope_ ? 1 : 0) + + (chanSystem_ ? 1 : 0) + (chanSass_ ? 1 : 0)) + : (resolveChannel(ch) ? 1u : 0u); + if (planned_copies == 0) return; + const std::uint64_t event_bytes = + static_cast(json.size() + 1); + const std::uint64_t incoming_bytes = + event_bytes > + std::numeric_limits::max() / planned_copies + ? std::numeric_limits::max() + : event_bytes * planned_copies; + const std::uint64_t estimated = + spool_estimated_bytes_.load(std::memory_order_relaxed); + const std::uint64_t available_estimate = + available_bytes_estimate_.load(std::memory_order_relaxed); + const bool near_spool_limit = + max_spool_bytes_ > 0 && + (estimated >= max_spool_bytes_ || + incoming_bytes >= max_spool_bytes_ - estimated); + const bool needs_space_baseline = + min_free_bytes_ > 0 && + available_estimate == std::numeric_limits::max(); + const bool near_space_reserve = + min_free_bytes_ > 0 && !needs_space_baseline && + (available_estimate <= min_free_bytes_ || + incoming_bytes >= available_estimate - min_free_bytes_); + if (near_spool_limit || needs_space_baseline || near_space_reserve) { + checkSpoolBudget(/*force=*/true, incoming_bytes); + if (spool_saturated_.load(std::memory_order_acquire)) { + dropped_events_.fetch_add(1, std::memory_order_relaxed); + dropped_bytes_.fetch_add(event_bytes, std::memory_order_relaxed); + return; + } + } std::uint64_t copies_written = 0; if (ch == Channel::All) { if (chanDevice_ && chanDevice_->write(json)) ++copies_written; @@ -683,8 +739,15 @@ void FileLogSink::write(Channel ch, std::string_view json) { spool_estimated_bytes_.fetch_add( bytes, std::memory_order_relaxed) + bytes; - if (max_spool_bytes_ > 0 && estimated >= max_spool_bytes_) { - checkSpoolBudget(/*force=*/true); + auto available = + available_bytes_estimate_.load(std::memory_order_relaxed); + while (available != std::numeric_limits::max()) { + const std::uint64_t reduced = + bytes >= available ? 0 : available - bytes; + if (available_bytes_estimate_.compare_exchange_weak( + available, reduced, std::memory_order_relaxed)) { + break; + } } } } diff --git a/include/gpufl/core/logger/file_log_sink.hpp b/include/gpufl/core/logger/file_log_sink.hpp index 671cb67..8c57308 100644 --- a/include/gpufl/core/logger/file_log_sink.hpp +++ b/include/gpufl/core/logger/file_log_sink.hpp @@ -7,6 +7,7 @@ #include #include #include +#include #include #include #include @@ -192,7 +193,8 @@ class FileLogSink final : public ILogSink { void enqueueRetired(FileChannel* channel, std::size_t index, std::uint64_t bytes, WindowTiming timing); void stopRetirementWorker(); - void checkSpoolBudget(bool force = false); + void checkSpoolBudget(bool force = false, + std::uint64_t incoming_bytes = 0); void markSpoolSaturated(std::uint64_t spool_bytes, std::uint64_t available_bytes, const char* reason); @@ -217,6 +219,11 @@ class FileLogSink final : public ILogSink { mutable std::mutex spool_budget_mu_; std::int64_t last_spool_check_ms_ = -1; std::atomic spool_estimated_bytes_{0}; + // Conservative free-space estimate from the last fs::space() scan, + // decremented by accepted writes. Agent deletions can only make the real + // value larger; approaching the reserve forces a fresh scan. + std::atomic available_bytes_estimate_{ + std::numeric_limits::max()}; std::atomic spool_saturated_{false}; std::atomic spool_bytes_at_saturation_{0}; std::atomic dropped_events_{0}; diff --git a/tests/core/test_file_log_sink_rotation.cpp b/tests/core/test_file_log_sink_rotation.cpp index 8172f9b..93203cb 100644 --- a/tests/core/test_file_log_sink_rotation.cpp +++ b/tests/core/test_file_log_sink_rotation.cpp @@ -818,7 +818,9 @@ TEST_F(FileLogSinkRotationTest, fs::file_size(tmpDir() / "device.log"); sink.write(gpufl::Channel::Device, R"({"must":"drop"})"); EXPECT_EQ(fs::file_size(tmpDir() / "device.log"), bytes_before); - EXPECT_EQ(sink.rotationStats().dropped_events, 1u); + EXPECT_EQ(sink.rotationStats().dropped_events, 2u) + << "the write that crosses the cap and every later write are both " + "rejected"; EXPECT_GT(sink.rotationStats().dropped_bytes, 0u); sink.close(); @@ -827,6 +829,54 @@ TEST_F(FileLogSinkRotationTest, "signal"; } +TEST_F(FileLogSinkRotationTest, + FilesystemReserveIsCheckedBeforeTheFirstEvent) { + std::error_code ec; + const auto available = fs::space(base_, ec).available; + ASSERT_FALSE(ec); + + auto opt = options(/*rotate_after_ms=*/0); + opt.max_spool_bytes = 0; + opt.min_free_bytes = available; + gpufl::FileLogSink sink(opt); + + ASSERT_TRUE(sink.rotationStats().spool_saturated); + sink.write(gpufl::Channel::Device, std::string(1024, 'x')); + EXPECT_EQ(sink.rotationStats().dropped_events, 1u); + EXPECT_EQ(fs::file_size(tmpDir() / "device.log"), 0u); + EXPECT_EQ(gpufl::transportLossMarkerCount(sessionDir()), 1u); +} + +TEST_F(FileLogSinkRotationTest, + ProjectedWriteCannotCrossTheRealFilesystemReserve) { + constexpr std::uint64_t kMargin = 8ull * 1024 * 1024; + constexpr std::uint64_t kWrite = 16ull * 1024 * 1024; + std::error_code ec; + const auto available = fs::space(base_, ec).available; + ASSERT_FALSE(ec); + if (available <= kMargin * 2) { + GTEST_SKIP() << "test filesystem has too little headroom"; + } + + auto opt = options(/*rotate_after_ms=*/0); + opt.max_spool_bytes = 0; + opt.min_free_bytes = available - kMargin; + gpufl::FileLogSink sink(opt); + ASSERT_FALSE(sink.rotationStats().spool_saturated) + << "external disk use consumed the test margin during setup"; + + sink.write( + gpufl::Channel::Device, + std::string(static_cast(kWrite), 'x')); + + EXPECT_TRUE(sink.rotationStats().spool_saturated); + EXPECT_EQ(sink.rotationStats().dropped_events, 1u); + EXPECT_EQ(fs::file_size(tmpDir() / "device.log"), 0u) + << "the write that would cross the reserve must be rejected before " + "touching the active window"; + EXPECT_EQ(gpufl::transportLossMarkerCount(sessionDir()), 1u); +} + TEST_F(FileLogSinkRotationTest, ZeroSpoolLimitsExplicitlyDisableTheGuard) { auto opt = options(/*rotate_after_ms=*/0); opt.flush_always = true;