diff --git a/.gitignore b/.gitignore index 7173bf1..91efea6 100644 --- a/.gitignore +++ b/.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 diff --git a/README.en.md b/README.en.md index bdf2f1a..a8be17e 100644 --- a/README.en.md +++ b/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 diff --git a/README.md b/README.md index 3500825..a9b73b8 100644 --- a/README.md +++ b/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`。滚动之后版本 +信息会重写一遍。媒体库扫描会给库里每个容器写日志，体量主要来自这里。 ## 已知限制 diff --git a/src/container_scan.cpp b/src/container_scan.cpp index 0f6ad0f..ef5503f 100644 --- a/src/container_scan.cpp +++ b/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; diff --git a/src/input_joc.cpp b/src/input_joc.cpp index 06fecc6..a3fe49e 100644 --- a/src/input_joc.cpp +++ b/src/input_joc.cpp @@ -17,6 +17,8 @@ #include #include +#include +#include #include #include @@ -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 g_declined{0}; +std::atomic 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(), - error.what()); + decline("decoder: not a native file path (%s): %s", m_path.c_str(), 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,8 +290,8 @@ 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)", - m_container.detail.c_str()); + decline("decoder: yielding to the built-in decoder (%s)", + m_container.detail.c_str()); throw exception_io_unsupported_format(); } @@ -273,20 +300,20 @@ 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", - detail.c_str()); + decline("decoder: cannot examine the E-AC-3 track (%s); yielding", 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 " - "no JOC: %s)", - m_container.audio_index, detail.c_str()); + 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(); } 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; } diff --git a/src/log.cpp b/src/log.cpp index 3b190f9..c0cfe0d 100644 --- a/src/log.cpp +++ b/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; -bool g_capped = false; +std::wstring g_wide_rolled; // g_wide_path with the .1 suffix +unsigned long long g_bytes = 0; -// A Media Library scan calls into us for every file; the cap keeps a long -// session from filling the disk, and says so once when it is reached. -constexpr unsigned long long kMaxLines = 500000; +// A Media Library scan calls into us for every file it walks, so the cap has to +// be on bytes: the lines a scan produces run from 40 to 2048 bytes each, and a +// 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(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(length) < sizeof(composed)) + ? static_cast(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, ...) { - va_list args; - va_start(args, fmt); +unsigned long long budget_bytes() { return kMaxBytes; } + +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 guard(g_mutex); if (!g_opened) open_locked(); if (g_file == nullptr) return; - if (g_lines >= kMaxLines) { - if (!g_capped) { - g_capped = true; - std::fputs("[log capped]\n", g_file); - } - return; - } - ++g_lines; + if (write_locked(text) != 0 && g_bytes >= kMaxBytes) roll_locked(); +} - SYSTEMTIME now; - GetLocalTime(&now); - std::fprintf(g_file, "%02u:%02u:%02u.%03u [t%05lu] %s\n", now.wHour, now.wMinute, - now.wSecond, now.wMilliseconds, - static_cast(GetCurrentThreadId()), text); +void line(const char* fmt, ...) { + va_list args; + va_start(args, fmt); + line_v(fmt, args); + va_end(args); +} + +void header_begin() { + std::lock_guard guard(g_mutex); + g_header.clear(); + g_recording = true; +} + +void header_end() { + std::lock_guard guard(g_mutex); + g_recording = false; } } // namespace joc_log diff --git a/src/log.h b/src/log.h index c7a9b28..4050858 100644 --- a/src/log.h +++ b/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 \joc_decoder.log. -// The file is truncated once per process, line-buffered, and every line is -// flushed so the log can be read while foobar2000 is still running. +// The file is truncated once per process, unbuffered, and every line is written +// 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 .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 +// . 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 + 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 .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 diff --git a/src/main.cpp b/src/main.cpp index c73e10d..69240d4 100644 --- a/src/main.cpp +++ b/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 ==="); } diff --git a/tests/log_rotation_test.cpp b/tests/log_rotation_test.cpp new file mode 100644 index 0000000..9ceb620 --- /dev/null +++ b/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 + +#include +#include + +#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(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(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; +} diff --git a/tools/build_tests.ps1 b/tools/build_tests.ps1 index a3a523d..202ec52 100644 --- a/tools/build_tests.ps1 +++ b/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",