Bound the diagnostic log and cut the per-file scan noise

.gitignore

@@ -27,8 +27,9 @@
 *.personalized_headphone
 rosella_kernels.npz
 
-# The component writes its own log next to the DLL
+# The component writes its own log next to the DLL, and rolls it to a .1 sibling
 joc_decoder.log
+joc_decoder.log.1
 
 # Measurement record: local working notes, kept on disk and never published.
 VERIFICATION.md

README.en.md

@@ -94,7 +94,11 @@ and test-bed scripts. Settings also read `JOC_*` environment overrides for one r
 only); the list and what each one does is in `src\settings.cpp`.
 
 To diagnose a problem, read `joc_decoder.log` beside the DLL: the component writes its own
-version, the core version and the log path there at start-up.
+version, the core version and the log path there at start-up. The log is capped by **bytes**: a
+file that reaches 16 MiB is rolled to `joc_decoder.log.1` beside it, replacing the previous roll
+rather than accumulating, so the two together never exceed 32 MiB and the newest lines are always
+in `joc_decoder.log`. The version banner is written again after a roll. A Media Library scan logs
+every container in the library, which is where the volume comes from.
 
 ## Known limitations
 

README.md

@@ -82,7 +82,9 @@ pwsh -File tools/package.ps1            # 两个架构，打包到 dist\*.fb2k-c
 另有 `JOC_*` 环境变量覆盖（仅用于开发运行），清单与含义在 `src\settings.cpp`。
 
 排查问题看 DLL 旁边的 `joc_decoder.log`；组件启动时会把自己的版本、核心版本、日志路径写在
-里面。
+里面。日志按**字节**封顶：单个文件写满 16 MiB 就滚到同目录的 `joc_decoder.log.1`（覆盖上一次
+滚动，不累积），所以两份加起来不超过 32 MiB，最新的内容始终在 `joc_decoder.log`。滚动之后版本
+信息会重写一遍。媒体库扫描会给库里每个容器写日志，体量主要来自这里。
 
 ## 已知限制
 

src/container_scan.cpp

@@ -22,6 +22,16 @@ std::wstring utf8_to_wide(const std::string& text) {
     return out;
 }
 
+// A library scan probes every container in the library, and most of them are
+// declined; they also mostly share a directory, so the path would spend the log's
+// byte budget repeating the same prefix once per file.  The file name is what
+// identifies the line.  Files this component claims are logged with their full
+// path by the caller.
+std::string file_name_of(const std::string& path) {
+    const std::string::size_type slash = path.find_last_of("\\/");
+    return (slash == std::string::npos) ? path : path.substr(slash + 1);
+}
+
 // A bounded, read-only view of the file.  Every accessor returns false instead of
 // throwing, so a truncated or hostile file simply fails the probe.
 class Window {
@@ -534,7 +544,7 @@ Result scan(const std::string& path, std::size_t max_bytes) {
     } else {
         result = scan_mp4(file, max_bytes);
     }
-    joc_log::line("container: %s -> %s (eac3=%d audio#%u codec=%s)", path.c_str(),
+    joc_log::line("container: %s -> %s (eac3=%d audio#%u codec=%s)", file_name_of(path).c_str(),
                   result.detail.c_str(), result.eac3 ? 1 : 0, result.audio_index,
                   result.codec.empty() ? "-" : result.codec.c_str());
     return result;

src/input_joc.cpp

@@ -17,6 +17,8 @@
 #include <SDK/input_impl.h>
 #include <SDK/tag_processor.h>
 
+#include <atomic>
+#include <cstdarg>
 #include <cstring>
 #include <string>
 
@@ -66,6 +68,31 @@ std::string file_name_of(const std::string& path) {
     return slash == std::string::npos ? path : path.substr(slash + 1);
 }
 
+// A library scan opens every container in the library through open(), and all but
+// a few of them are declined because their audio is not E-AC-3 JOC.  The per-file
+// lines are what makes a scan diagnosable -- "the file that should have been
+// claimed was not, and here is why" -- but a large library is hundreds of
+// thousands of them, so a running summary is logged as well.  It is short enough
+// to survive the log rolling over, which is what a scan of that size makes it do.
+constexpr unsigned kDeclineSummaryEvery = 1000;
+std::atomic<unsigned> g_declined{0};
+std::atomic<unsigned> g_claimed{0};
+
+// One place for "this file is not ours".  The message stays the caller's, so a
+// decline that failed rather than decided still reads as one.
+void decline(const char* fmt, ...) {
+    va_list args;
+    va_start(args, fmt);
+    joc_log::line_v(fmt, args);
+    va_end(args);
+
+    const unsigned count = g_declined.fetch_add(1, std::memory_order_relaxed) + 1;
+    if ((count % kDeclineSummaryEvery) == 0u) {
+        joc_log::line("scan: %u file(s) declined, %u claimed so far", count,
+                      g_claimed.load(std::memory_order_relaxed));
+    }
+}
+
 // ---------------------------------------------------------------------------
 // Tags of a file this component has taken over.
 //
@@ -200,8 +227,7 @@ public:
         try {
             m_native_path = filesystem::g_get_native_path(m_path.c_str());
         } catch (const pfc::exception& error) {
-            joc_log::line("decoder: not a native file path (%s): %s", m_path.c_str(),
+            decline("decoder: not a native file path (%s): %s", m_path.c_str(), error.what());
-                          error.what());
             throw exception_io_unsupported_format();
         }
 
@@ -249,10 +275,11 @@ public:
 
         if (scan.joc != joc_eac3::JocState::kYes) {
             // Hand the file to the next entry in the priority table.
-            joc_log::line("decoder: yielding to the built-in decoder (%s)", scan.detail);
+            decline("decoder: yielding to the built-in decoder (%s)", scan.detail);
             throw exception_io_unsupported_format();
         }
         joc_log::line("decoder: claiming this file as E-AC-3 JOC (bare stream)");
+        g_claimed.fetch_add(1, std::memory_order_relaxed);
         m_input_kind = joc_decode::InputKind::kBare;
     }
 
@@ -263,7 +290,7 @@ public:
     void open_container(const char* extension) {
         m_container = joc_container::scan(m_native_path.get_ptr());
         if (!m_container.eac3) {
-            joc_log::line("decoder: yielding to the built-in decoder (%s)",
+            decline("decoder: yielding to the built-in decoder (%s)",
                     m_container.detail.c_str());
             throw exception_io_unsupported_format();
         }
@@ -273,12 +300,11 @@ public:
         std::string detail;
         if (!joc_decode::probe_container_joc(settings.ffmpeg_path, m_native_path.get_ptr(),
                                             m_container.audio_index, &joc, &detail)) {
-            joc_log::line("decoder: cannot examine the E-AC-3 track (%s); yielding",
+            decline("decoder: cannot examine the E-AC-3 track (%s); yielding", detail.c_str());
-                          detail.c_str());
             throw exception_io_unsupported_format();
         }
         if (!joc) {
-            joc_log::line("decoder: yielding to the built-in decoder (E-AC-3 track %u carries "
+            decline("decoder: yielding to the built-in decoder (E-AC-3 track %u carries "
                     "no JOC: %s)",
                     m_container.audio_index, detail.c_str());
             throw exception_io_unsupported_format();
@@ -287,6 +313,7 @@ public:
         joc_log::line("decoder: claiming this file as E-AC-3 JOC (%s, audio track %u, .%s)",
                       joc_container::kind_name(m_container.kind), m_container.audio_index,
                       extension);
+        g_claimed.fetch_add(1, std::memory_order_relaxed);
         m_input_kind = joc_decode::InputKind::kContainer;
         m_audio_index = m_container.audio_index;
     }

src/log.cpp

@@ -16,12 +16,20 @@ FILE* g_file = nullptr;
 bool g_opened = false;
 std::string g_path;          // UTF-8, for reporting
 std::wstring g_wide_path;    // for _wfopen
-unsigned long long g_lines = 0;
+std::wstring g_wide_rolled;  // g_wide_path with the .1 suffix
-bool g_capped = false;
+unsigned long long g_bytes = 0;
 
-// A Media Library scan calls into us for every file; the cap keeps a long
+// A Media Library scan calls into us for every file it walks, so the cap has to
-// session from filling the disk, and says so once when it is reached.
+// be on bytes: the lines a scan produces run from 40 to 2048 bytes each, and a
-constexpr unsigned long long kMaxLines = 500000;
+// cap on their number leaves the file they build unpredictable by a factor of
+// fifty.  Sixteen mebibytes per file, one previous file kept, so the component
+// never holds more than 32 MiB of log.
+constexpr unsigned long long kMaxBytes = 16ull << 20;
+
+// The lines recorded between header_begin() and header_end(): the version
+// banner, a handful of lines written once per process.
+bool g_recording = false;
+std::string g_header;
 
 std::wstring module_directory() {
     HMODULE module = nullptr;
@@ -64,6 +72,7 @@ void open_locked() {
         g_wide_path = dir + L"\\joc_decoder.log";
     }
 
+    g_wide_rolled = g_wide_path + L".1";
     g_path = to_utf8(g_wide_path);
     g_file = _wfopen(g_wide_path.c_str(), L"wb");
     if (g_file == nullptr) {
@@ -74,6 +83,52 @@ void open_locked() {
     std::setvbuf(g_file, nullptr, _IONBF, 0);
 }
 
+// Composes one line with its timestamp, writes it, and accounts for it.  Returns
+// the bytes written, 0 when there was nowhere to write them.
+unsigned long long write_locked(const char* text) {
+    if (g_file == nullptr) return 0;
+
+    SYSTEMTIME now;
+    GetLocalTime(&now);
+    char composed[2100];
+    const int length =
+        std::snprintf(composed, sizeof(composed), "%02u:%02u:%02u.%03u [t%05lu] %s\n", now.wHour,
+                      now.wMinute, now.wSecond, now.wMilliseconds,
+                      static_cast<unsigned long>(GetCurrentThreadId()), text);
+    if (length <= 0) return 0;
+    // snprintf reports the length it would have needed, which for a truncated
+    // line is past the end of the buffer.
+    const std::size_t size = (static_cast<std::size_t>(length) < sizeof(composed))
+                                 ? static_cast<std::size_t>(length)
+                                 : sizeof(composed) - 1;
+    std::fwrite(composed, 1, size, g_file);
+    g_bytes += size;
+    if (g_recording) g_header.append(composed, size);
+    return size;
+}
+
+// Moves the full file aside and starts an empty one.  Called with the mutex held,
+// once the budget is spent.  The banner is written again afterwards, so a log
+// that has rolled still opens with the versions it was produced by.
+void roll_locked() {
+    std::fclose(g_file);
+    g_file = nullptr;
+    // One previous window, replaced rather than chained: a chain of rolls would
+    // be the same unbounded log under another name.  A move that fails -- the .1
+    // file held open by a reader -- leaves the truncation below to bound the file
+    // anyway, at the cost of the window that would have been kept.
+    MoveFileExW(g_wide_path.c_str(), g_wide_rolled.c_str(), MOVEFILE_REPLACE_EXISTING);
+    g_file = _wfopen(g_wide_path.c_str(), L"wb");
+    if (g_file == nullptr) return;
+    std::setvbuf(g_file, nullptr, _IONBF, 0);
+    g_bytes = 0;
+    write_locked("[log rolled: the previous window is in the .1 file beside this one]");
+    if (!g_header.empty()) {
+        std::fwrite(g_header.c_str(), 1, g_header.size(), g_file);
+        g_bytes += g_header.size();
+    }
+}
+
 }  // namespace
 
 void open() {
@@ -86,30 +141,34 @@ const char* path() {
     return g_path.c_str();
 }
 
-void line(const char* fmt, ...) {
+unsigned long long budget_bytes() { return kMaxBytes; }
-    va_list args;
+
-    va_start(args, fmt);
+void line_v(const char* fmt, va_list args) {
     char text[2048];
     std::vsnprintf(text, sizeof(text), fmt, args);
-    va_end(args);
 
     std::lock_guard<std::mutex> guard(g_mutex);
     if (!g_opened) open_locked();
     if (g_file == nullptr) return;
-    if (g_lines >= kMaxLines) {
+    if (write_locked(text) != 0 && g_bytes >= kMaxBytes) roll_locked();
-        if (!g_capped) {
-            g_capped = true;
-            std::fputs("[log capped]\n", g_file);
 }
-        return;
-    }
-    ++g_lines;
 
-    SYSTEMTIME now;
+void line(const char* fmt, ...) {
-    GetLocalTime(&now);
+    va_list args;
-    std::fprintf(g_file, "%02u:%02u:%02u.%03u [t%05lu] %s\n", now.wHour, now.wMinute,
+    va_start(args, fmt);
-                 now.wSecond, now.wMilliseconds,
+    line_v(fmt, args);
-                 static_cast<unsigned long>(GetCurrentThreadId()), text);
+    va_end(args);
+}
+
+void header_begin() {
+    std::lock_guard<std::mutex> guard(g_mutex);
+    g_header.clear();
+    g_recording = true;
+}
+
+void header_end() {
+    std::lock_guard<std::mutex> guard(g_mutex);
+    g_recording = false;
 }
 
 }  // namespace joc_log

src/log.h

@@ -4,10 +4,22 @@
 // harness and so that it is safe to call from any thread the core queries us on.
 //
 // Path: %JOC_LOG% if set, otherwise <directory of this DLL>\joc_decoder.log.
-// The file is truncated once per process, line-buffered, and every line is
+// The file is truncated once per process, unbuffered, and every line is written
-// flushed so the log can be read while foobar2000 is still running.
+// straight out so the log can be read while foobar2000 is still running.
+//
+// Size: what is bounded is bytes, not lines.  A line is anywhere between 40 and
+// 2048 bytes, so a cap on the number of lines leaves the size of the file
+// unpredictable by a factor of fifty.  A file that reaches budget_bytes() is
+// moved to <path>.1 -- replacing any previous roll, so there is never a chain of
+// them -- and a fresh one is started.  Two files of the budget is therefore the
+// most the component ever holds, and the newest lines are always the ones in
+// <path>.  Lines written between header_begin() and header_end() are written
+// again at the top of every window, so a rolled log still says which build
+// produced it.
 #pragma once
 
+#include <cstdarg>
+
 namespace joc_log {
 
 // Opens (truncating) the log.  Called lazily by line(); call it explicitly to
@@ -17,7 +29,18 @@ void open();
 // Absolute path of the log file, or "" when it could not be opened.
 const char* path();
 
+// Bytes one file holds before it is rolled to <path>.1.
+unsigned long long budget_bytes();
+
 // printf-style, thread safe, appends one line.
 void line(const char* fmt, ...);
 
+// The va_list form, for a wrapper that forwards its own arguments.
+void line_v(const char* fmt, va_list args);
+
+// Remembers the lines written in between and writes them again after every roll.
+// Meant for the version banner: a handful of lines, written once.
+void header_begin();
+void header_end();
+
 }  // namespace joc_log

src/main.cpp

@@ -30,6 +30,9 @@ class joc_initquit : public initquit {
 public:
     void on_init() override {
         joc_log::open();
+        // Recorded, so that a log which has rolled still opens with the versions
+        // it was produced by.
+        joc_log::header_begin();
         joc_log::line("=== foo_input_joc %s ===", JOC_VERSION);
         joc_log::line("foobar2000 core : %s", core_version_info::g_get_version_string());
         joc_log::line("component file  : %s", core_api::get_my_file_name());
@@ -37,6 +40,8 @@ public:
         joc_log::line("portable mode   : %s",
                       core_api::is_portable_mode_enabled() ? "yes" : "no");
         joc_log::line("log file        : %s", joc_log::path());
+        joc_log::line("log limit       : %llu byte(s) per file, then rolled to the .1 suffix",
+                      joc_log::budget_bytes());
         joc_log::line("compiled as     : %s",
 #if defined(_M_IX86)
                       "x86 (32-bit)"
@@ -46,6 +51,7 @@ public:
                       "other"
 #endif
         );
+        joc_log::header_end();
     }
 
     void on_quit() override { joc_log::line("=== foo_input_joc shutdown ==="); }

tests/log_rotation_test.cpp

@@ -0,0 +1,111 @@
+// Drives the diagnostic log past its byte budget, without foobar2000.
+//
+//   log_rotation_test
+//
+// The component's log is bounded by rolling: a file that reaches the budget is
+// moved to a .1 sibling and a fresh one is started.  What pushes it there is a
+// Media Library scan, which a test cannot arrange, so the budget is spent here
+// with lines of a known size instead.  What is checked is what the bound
+// promises: neither file passes the budget, there is no chain of rolls, the
+// newest lines are the ones in the live file, and the session banner is written
+// again after a roll -- which is the only reason a rolled log still says which
+// build produced it.
+
+#include <windows.h>
+
+#include <cstdio>
+#include <string>
+
+#include "../src/log.h"
+
+namespace {
+
+std::wstring temp_directory() {
+    wchar_t buffer[MAX_PATH + 1] = {};
+    const DWORD length = GetTempPathW(MAX_PATH, buffer);
+    return std::wstring(buffer, length) + L"joc_log_rotation_test";
+}
+
+bool read_file(const std::wstring& path, std::string* out) {
+    std::FILE* file = _wfopen(path.c_str(), L"rb");
+    if (file == nullptr) return false;
+    char buffer[64 * 1024];
+    std::size_t got = 0;
+    while ((got = std::fread(buffer, 1, sizeof(buffer), file)) != 0) out->append(buffer, got);
+    std::fclose(file);
+    return true;
+}
+
+unsigned long long file_size(const std::wstring& path) {
+    WIN32_FILE_ATTRIBUTE_DATA data{};
+    if (GetFileAttributesExW(path.c_str(), GetFileExInfoStandard, &data) == FALSE) return 0;
+    return (static_cast<unsigned long long>(data.nFileSizeHigh) << 32) | data.nFileSizeLow;
+}
+
+bool contains(const std::string& haystack, const std::string& needle) {
+    return haystack.find(needle) != std::string::npos;
+}
+
+int failures = 0;
+
+void check(bool ok, const char* what) {
+    std::printf("%-4s %s\n", ok ? "ok" : "FAIL", what);
+    if (!ok) ++failures;
+}
+
+}  // namespace
+
+int main() {
+    const std::wstring dir = temp_directory();
+    CreateDirectoryW(dir.c_str(), nullptr);
+    const std::wstring live = dir + L"\\rotation.log";
+    const std::wstring rolled = live + L".1";
+    const std::wstring chained = live + L".2";
+    DeleteFileW(live.c_str());
+    DeleteFileW(rolled.c_str());
+    DeleteFileW(chained.c_str());
+    SetEnvironmentVariableW(L"JOC_LOG", live.c_str());
+
+    const unsigned long long budget = joc_log::budget_bytes();
+    std::printf("budget %llu byte(s) per file\n", budget);
+
+    joc_log::open();
+    joc_log::header_begin();
+    joc_log::line("=== header marker ===");
+    joc_log::header_end();
+
+    // Enough lines to spend the budget twice over, so the roll has to happen and
+    // the file it produces has to be replaced rather than added to.
+    const std::string filler(160, 'x');
+    const unsigned lines = static_cast<unsigned>(budget / 190ull * 3ull);
+    for (unsigned i = 1; i <= lines; ++i) joc_log::line("filler %u %s", i, filler.c_str());
+
+    const unsigned long long live_size = file_size(live);
+    const unsigned long long rolled_size = file_size(rolled);
+    std::printf("wrote %u line(s): live %llu byte(s), rolled %llu byte(s)\n", lines, live_size,
+                rolled_size);
+
+    check(live_size > 0 && live_size <= budget + 4096, "live file is inside the budget");
+    check(rolled_size > 0 && rolled_size <= budget + 4096, "rolled file is inside the budget");
+    check(live_size + rolled_size <= 2 * budget + 8192, "the two together are inside twice it");
+    check(file_size(chained) == 0, "no second roll is kept");
+
+    std::string live_text;
+    std::string rolled_text;
+    check(read_file(live, &live_text), "live file reads back");
+    check(read_file(rolled, &rolled_text), "rolled file reads back");
+    check(contains(live_text, "[log rolled"), "the live file says it rolled");
+    check(contains(live_text, "=== header marker ==="), "the banner was written again");
+
+    char newest[64] = {};
+    std::snprintf(newest, sizeof(newest), "filler %u ", lines);
+    check(contains(live_text, newest), "the newest line is in the live file");
+    check(!contains(rolled_text, newest), "and not in the rolled one");
+
+    if (failures == 0) {
+        std::printf("log rotation holds\n");
+        return 0;
+    }
+    std::printf("%d check(s) failed\n", failures);
+    return 1;
+}

tools/build_tests.ps1

@@ -40,6 +40,7 @@ $lines = @(
     "cd /d `"$projectRoot`"",
     # log.cpp comes along because the engine writes its diagnostics through it.
     "cl $common /Fe:`"$outDir\container_scan_test.exe`" /Fo:`"$outDir\\`" tests\container_scan_test.cpp src\container_scan.cpp src\log.cpp",
+    "cl $common /Fe:`"$outDir\log_rotation_test.exe`" /Fo:`"$outDir\\`" tests\log_rotation_test.cpp src\log.cpp",
     "cl $common /Fe:`"$outDir\scan_selftest.exe`" /Fo:`"$outDir\\`" tests\scan_selftest.cpp src\eac3_scan.cpp",
     "cl $common /Fe:`"$outDir\prefs_layout_check.exe`" /Fo:`"$outDir\\`" tests\prefs_layout_check.cpp user32.lib gdi32.lib",
     "cl $common /Fe:`"$outDir\scan_crosscheck.exe`" /Fo:`"$outDir\\`" tests\scan_crosscheck.cpp src\eac3_scan.cpp `"$coreLib`" shell32.lib",