diff --git a/.github/workflows/smoke.yml b/.github/workflows/smoke.yml index 9f5ccc5..3e35a7c 100644 --- a/.github/workflows/smoke.yml +++ b/.github/workflows/smoke.yml @@ -306,6 +306,13 @@ jobs: - name: Run etc_webhook unit test run: lua5.4 tests/unit/etc_webhook_test.lua + # etc_cmdlog (#460): the command log is stored language-neutral and + # re-localized at read-time. Verifies an entry written under one + # language renders in the current language after a switch, old baked + # lines fall back to raw, control bytes are stripped, HTTP re-localizes. + - name: Run etc_cmdlog unit test + run: lua5.4 tests/unit/etc_cmdlog_test.lua + - name: Configure run: cmake -B build -DCMAKE_BUILD_TYPE=Release @@ -548,6 +555,10 @@ jobs: shell: msys2 {0} run: lua5.4 tests/unit/etc_webhook_test.lua + - name: Run etc_cmdlog unit test + shell: msys2 {0} + run: lua5.4 tests/unit/etc_cmdlog_test.lua + - name: Configure shell: msys2 {0} run: cmake -B build -G "MinGW Makefiles" -DCMAKE_BUILD_TYPE=Release -DOPENSSL_ROOT_DIR=/ucrt64 diff --git a/CHANGELOG.md b/CHANGELOG.md index 66789d9..1d9b427 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -85,6 +85,8 @@ land on `release/3.1.x` per ### Bugfixes +- **`etc_cmdlog`: `+cmdlog show` and `GET /v1/log/cmd` showed a frozen, possibly mixed-language log because the language labels were baked into each line at write-time** ([#460](https://github.com/luadch-ng/luadch/issues/460)). The `onBroadcast` writer stored `date .. msg1 .. cmd .. args .. msg2 .. nick`, embedding the labels active *when the command ran*; both readers dumped the file raw and never re-formatted. So every entry was frozen in its write-time language, a hub whose `cfg.language` changed showed a **mix**, and on a German hub whose entries all predated the switch `+cmdlog show` printed English (`Command:` / `used by:`) despite every other plugin reporting German. Distinct from the v1.4 `#301`-class fix below (that one was unreachable lang keys; this is a design flaw in *when* localization happens). Fixed by storing entries **language-neutral** - four fields (`ts`, `cmd`, `args`, `nick`) separated by the US control byte (`0x1f`) - and applying the current `msg1` / `msg2` labels at **read-time** via one shared `render_line`, on both the ADC and HTTP path, so old and new entries alike render in the hub's current language. Migration is automatic and lossless: an old baked line has no delimiter, so `render_line` returns it as-is (its frozen language) rather than dropping or mis-parsing it. Every field is run through `util.strip_control_bytes` at write-time, which both keeps the delimiter out of any field and closes a **latent corruption** where a newline in a command's arguments split one entry across two log lines. The `GET /v1/log/cmd` response contract is **unchanged** (`{lines:[string], returned, total_lines}`); its lines are simply re-localized now instead of frozen - so no `docs/HTTP_API.md` change was needed. Returning structured fields there is a possible future contract improvement, deliberately deferred to keep this a non-breaking language fix. `etc_cmdlog` v1.4 -> v1.5. Provably fails pre-fix (§1a.7): a new unit test (`tests/unit/etc_cmdlog_test.lua`, both smoke.yml legs) writes an entry under `en`, switches the hub to `de`, and asserts `+cmdlog show` renders `Befehl:` / `benutzt von:` - on the unpatched plugin the labels are baked English and it fails; it also covers the old-line raw fallback, a mixed-language file, redacted-arg storage, control-byte stripping, and the HTTP path. 3.2.x only, not backported. + - **`etc_records`: a missing / empty / corrupt `etc_records.tbl` crashed `onLogin` for every user** ([#465](https://github.com/luadch-ng/luadch/issues/465)). The record store is a positional 8-slot table; the load did `util.loadtable(p) or { }`, which guards a nil *table* but not nil *slots*. With an empty or truncated file `records[3]` / `[6]` / `[8]` were `nil`, and the max-tracking comparisons `new > tonumber(records[N])` in `hubshare` (`[3]`), `onliners` (`[6]`) and `topshare` (`[8]`) - all three fired from `onLogin`, and `hubshare` also from the `onTimer` - raised **"attempt to compare nil with number"**, spamming the error log on each login until the file was restored. The plugin only worked because the shipped seed happened to be present; it did not actually tolerate the degraded state its own `or { }` implied. Fixed by seeding each slot at load to the same default shape `reset()` already builds (numeric maxes to `0`/`1`, dates/times to now, nick to `"none"`); existing values are preserved, and `tonumber(...) or N` also repairs a slot that persisted as a non-numeric string. `etc_records` v0.8 -> v0.9. Provably fails pre-fix (§1a.7): a new unit test (`tests/unit/etc_records_test.lua`, both smoke.yml legs) fires `onLogin` against empty / truncated / corrupt / per-slot-nil record tables and asserts no crash - on the unpatched plugin these raise the nil-compare **independently at each of the three sites** (`hubshare` :362, `onliners` :389, `topshare` :410), while a well-formed-file control still passes on both trees. Found while investigating #464, where an emptied `scripts/data/` in a smoke run surfaced this crash on every login. 3.2.x only, not backported. - **The lifetime "hub runtime" counter silently reset to zero on every upgrade** ([#445](https://github.com/luadch-ng/luadch/issues/445)). The persisted accumulator behind `+runtime show` / `+uptime` / `+hubinfo` / `GET /v1/runtime` lived in `core/hci.lua`. `core/` is a **shipped** directory - `CMakeLists.txt` does `install(DIRECTORY core/)` wholesale, and the Docker image bakes `core/` in rather than mounting it - so a source `cmake --install` over an existing tree, and every Docker image update, wrote the pristine `hubruntime = 0` straight over the operator's accumulated value. A **zeroed** file is indistinguishable from a fresh hub, so nothing detected the loss; a counter meant to survive restarts was wiped on the one event it most needed to survive. Fixed by moving the store to `scripts/data/hub_runtime.tbl` - the operator-owned, Docker-mounted plugin-state dir that upgrades never clobber (the CLAUDE.md §7 / DEVELOPMENT.md §3 rule this file always broke). `hub_runtime` (v0.9 -> v0.10) is now the **sole writer** and does a one-time migration on load: if the new store is absent it adopts the value from a legacy `core/hci.lua`. That adoption only recovers a value if the legacy file still holds it when the hub boots - and a naive `cmake --install` would zero `core/hci.lua` *before* boot (the very clobber #445 is about), so the migration would read zeros and recover nothing. The critical half of the fix is therefore in **`CMakeLists.txt`**: `install(DIRECTORY core/ ... PATTERN "hci.lua" EXCLUDE)` so a source upgrade leaves the operator's on-disk `core/hci.lua` untouched, letting the migration adopt the real value. Docker cannot migrate - its pre-fix counter lived in the container's ephemeral writable layer (`core/` is baked, not mounted) and was already discarded on every container recreate - but it gains a persistent counter going forward now that the store is on the mounted `scripts/data/` side. `cmd_uptime` (v0.10 -> v0.11) and `cmd_hubinfo` (v0.30 -> v0.31) became **pure readers** of the new path - their old `check_hci()` create-if-missing would otherwise have raced a zero file in ahead of the migration; `cmd_hubinfo` additionally now re-reads the store on each `+hubinfo` instead of caching it at plugin load (the cached value went stale as the 60s onTimer advanced the counter). `core/hci.lua` is kept read-only as the migration source and is no longer written by anything; a future release removes it. `docs/HTTP_API.md`, `docs/SCRIPTS.md` and `CLAUDE.md` §3 updated. Provably fails pre-fix (§1a.7): a new unit test (`tests/unit/hub_runtime_migration_test.lua`, both smoke.yml legs) exercises the pure migration decision + the load-time side effect over an in-memory fs; a `/v1/runtime` smoke stage asserts `scripts/data/hub_runtime.tbl` exists after a PUT (that file never existed pre-fix, when the store was `core/hci.lua`) and the PUT value did not leak into the shipped `core/hci.lua`; and the CMake exclusion was verified directly - seeding `core/hci.lua` to a non-zero value and re-running `cmake --install` preserves it with the `PATTERN EXCLUDE` and zeros it without (the exact scenario #445 describes). Found by the dead-code audit (`core/hci.lua` was flagged as a possible dead stub - it was neither, but the check surfaced this). 3.2.x only, not backported. diff --git a/scripts/etc_cmdlog.lua b/scripts/etc_cmdlog.lua index 0960848..2938be4 100644 --- a/scripts/etc_cmdlog.lua +++ b/scripts/etc_cmdlog.lua @@ -6,6 +6,19 @@ Usage: [+!#]cmdlog show + v1.5: + - fix (#460): the log baked the localized labels (msg1/msg2) into + each line at write-time, so "+cmdlog show" and GET /v1/log/cmd + never re-localized - every entry was frozen in whatever language + was active when it was logged, and a hub whose language changed + showed a mix. Entries are now stored language-neutral (fields + separated by the US control byte) and the labels are applied at + read-time in the current language, on both the ADC and HTTP path. + Old baked lines predating this version have no delimiter and are + rendered as-is (their frozen language) rather than dropped. + Control bytes in args/nick are now stripped, which also closes a + latent newline-in-args log-format corruption. + v1.4: - fix: the language lookups read "lang.failmsg1" / "lang.failmsg2", but the lang files define the keys as "msg_denied" / "msg_nofile" @@ -66,7 +79,7 @@ -------------- local scriptname = "etc_cmdlog" -local scriptversion = "1.4" +local scriptversion = "1.5" -- HTTP API tail-style cap per docs/HTTP_API.md §6.4. Same value -- as cmd_errors.lua for consistency across log endpoints. @@ -91,6 +104,16 @@ local utf_match = utf.match local utf_format = utf.format local os_date = os.date local io_open = io.open +local util_strip = util.strip_control_bytes +local table_concat = table.concat + +-- #460: entries are stored as US-delimited (0x1f) language-neutral +-- fields "ts cmd args nick". The delimiter is a control +-- byte, so strip_control_bytes (applied to every field at write-time) +-- guarantees it never appears inside a field; a line without it is an +-- old baked entry (v1.4 and earlier) rendered as-is at read-time. +local FIELD_SEP = "\31" +local LINE_PAT = "^([^\31]*)\31([^\31]*)\31([^\31]*)\31(.*)$" --// imports local logfile = "log/cmd.log" @@ -143,24 +166,45 @@ hub.setlistener( "onBroadcast", {}, else s2 = s2 or "" end + -- #460: store language-neutral fields; labels are applied at + -- read-time. strip_control_bytes keeps the delimiter out of any + -- field and prevents a newline in args from breaking the line. + -- Guard the open so a missing/unwritable log/ dir can't crash + -- this onBroadcast listener (which fires for every broadcast). local f = io_open( logfile, "a" ) - f:write( os_date( " [ %Y-%m-%d / %H:%M:%S ]" ) .. msg1 .. s1 .. " " .. s2 .. msg2 .. user:nick() .. "\n" ) - f:close() + if f then + f:write( os_date( "%Y-%m-%d / %H:%M:%S" ) .. FIELD_SEP .. util_strip( s1 ) .. FIELD_SEP .. util_strip( s2 ) .. FIELD_SEP .. util_strip( user:nick() ) .. "\n" ) + f:close() + end end return nil end ) +-- #460: render one stored line for display in the CURRENT language. A +-- new-format line is four US-delimited fields (ts, cmd, args, nick) and +-- gets the current msg1/msg2 labels here. A line without the delimiter +-- is an old baked entry (v1.4 and earlier) and is returned as-is so its +-- frozen language survives rather than being dropped or mis-parsed. +local render_line = function( line ) + local ts, c, a, n = line:match( LINE_PAT ) + if not ts then return line end + return " [ " .. ts .. " ]" .. msg1 .. c .. " " .. a .. msg2 .. n +end + local onbmsg = function( user, adccmd, parameters, txt ) local id = utf_match( parameters, "^(%S+)$" ) if id == cmd_p then if user:level() >= minlevel then - local msg, msg_log + local msg_log local file, err = io_open( logfile, "r" ) if file then - msg = file:read( "*a" ) + -- #460: render each stored line in the current language + -- (old baked lines pass through render_line unchanged). + local out = { } + for line in file:lines() do out[ #out + 1 ] = render_line( line ) end file:close() - msg_log = utf_format( msg_out, msg ) + msg_log = utf_format( msg_out, table_concat( out, "\n" ) ) user:reply( msg_log, hub_getbot, hub_getbot ) return PROCESSED else @@ -201,10 +245,11 @@ end -- HTTP handler: GET /v1/log/cmd?lines=N (#82 Phase 3 PR-4). -- Admin scope. Mirrors GET /v1/log/error (PR-3) shape: --- {lines: [string], returned: int, total_lines: int}. The ADC --- `+cmdlog show` path is unchanged and remains a whole-file dump --- through the chat banner; the HTTP path uses the same line-tail --- semantic as the other log endpoints. +-- {lines: [string], returned: int, total_lines: int}. Each tail line +-- is rendered in the hub's current language (#460) via the same +-- render_line as `+cmdlog show`, so the contract is unchanged (still +-- a list of display strings) but no longer frozen/mixed-language; old +-- baked lines pass through unchanged. -- -- The ADC-side `etc_cmdlog_minlevel` check does NOT apply on the -- HTTP path: the bearer token's `admin` scope IS the @@ -214,6 +259,7 @@ local http_handler_log_cmd = function( req ) if n < 1 then n = HTTP_DEFAULT_LINES end if n > HTTP_MAX_LINES then n = HTTP_MAX_LINES end local lines, total = read_log_tail( logfile, n ) + for i = 1, #lines do lines[ i ] = render_line( lines[ i ] ) end return { status = 200, data = { lines = lines, returned = #lines, diff --git a/tests/unit/etc_cmdlog_test.lua b/tests/unit/etc_cmdlog_test.lua new file mode 100644 index 0000000..97bdff9 --- /dev/null +++ b/tests/unit/etc_cmdlog_test.lua @@ -0,0 +1,236 @@ +--[[ + + tests/unit/etc_cmdlog_test.lua + + Regression test for scripts/etc_cmdlog.lua v1.5 (#460): the command + log must be stored language-neutral and re-localized at read-time, so + `+cmdlog show` renders in the hub's CURRENT language regardless of the + language that was active when each entry was written. + + Pre-fix (v1.4) the onBroadcast writer baked the localized labels + (msg1/msg2) into every stored line, and `+cmdlog show` dumped the file + raw - so an entry written on an English hub stayed English forever, + and a hub whose language later changed showed a frozen mix. Case 1 + below writes under "en", switches the hub to "de", and asserts show + renders the German labels - it FAILS on v1.4 (the file holds + "Command:" / "used by:") and PASSES on v1.5. + + The plugin gets NO `use`; every dependency is a sandbox-global stub. + An in-memory filesystem (_fs) persists across plugin reloads so a + write under one language is read back under another. + + Run: lua5.4 tests/unit/etc_cmdlog_test.lua + +]]-- + +local checks, failures = 0, 0 +local function ok( label, cond, extra ) + checks = checks + 1 + if not cond then failures = failures + 1 + io.write( "FAIL " .. label .. ( extra and ( " - " .. tostring( extra ) ) or "" ) .. "\n" ) + else io.write( "ok " .. label .. "\n" ) end +end +local function contains( hay, needle ) return type( hay ) == "string" and hay:find( needle, 1, true ) ~= nil end + +---------------------------------------------------------------------- +-- in-memory filesystem (persists across plugin reloads) +---------------------------------------------------------------------- +local _fs = { } + +local function fake_open( path, mode ) + mode = mode or "r" + if mode:find( "r" ) then + local content = _fs[ path ] + if content == nil then return nil, path .. ": no such file" end + return { + read = function( _, fmt ) return content end, -- only "*a" is used + lines = function( ) + local pos = 1 + return function( ) + if pos > #content then return nil end + local nl = content:find( "\n", pos, true ) + if nl then + local line = content:sub( pos, nl - 1 ); pos = nl + 1; return line + end + local line = content:sub( pos ); pos = #content + 1; return line + end + end, + close = function( ) end, + } + end + -- append / write + if mode:find( "a" ) then _fs[ path ] = _fs[ path ] or "" else _fs[ path ] = "" end + return { + write = function( _, ... ) + for _, s in ipairs( { ... } ) do _fs[ path ] = _fs[ path ] .. s end + end, + close = function( ) end, + } +end + +---------------------------------------------------------------------- +-- sandbox-global stubs +---------------------------------------------------------------------- +local _active_lang -- what cfg.loadlanguage returns +local _listeners -- event -> fn +local _onbmsg -- captured show handler +local _http -- captured http handler +local _last_reply -- last user:reply text + +_G.type = type; _G.pairs = pairs; _G.ipairs = ipairs +_G.tonumber = tonumber; _G.tostring = tostring +_G.string = string; _G.table = table; _G.math = math +_G.PROCESSED = "PROCESSED" + +local _real_os, _real_io = os, io +_G.utf = { match = string.match, format = string.format } +_G.os = setmetatable( { date = function( ) return "2026-07-18 / 12:00:00" end }, { __index = _real_os } ) +_G.io = setmetatable( { open = fake_open }, { __index = _real_io } ) + +_G.util = { + strip_control_bytes = function( s ) return ( type( s ) == "string" ) and ( s:gsub( "%c", "?" ) ) or "" end, +} + +_G.cfg = { + get = function( k ) + if k == "etc_cmdlog_minlevel" then return 10 end + if k == "etc_cmdlog_command_tbl" then return { accinfo = true, setpass = true, oldcmd = true } end + if k == "etc_cmdlog_redact_args" then return { setpass = true } end + if k == "language" then return "test" end + return nil + end, + loadlanguage = function( ) return _active_lang, nil end, +} + +_G.hub = { + getbot = function( ) return { } end, + setlistener = function( ev, _opts, fn ) _listeners[ ev ] = fn end, + debug = function( ) end, + http_register = function( _method, _path, _scope, fn ) _http = fn end, + import = function( name ) + if name == "cmd_help" then return { reg = function( ) end } end + if name == "etc_usercommands" then return { add = function( ) end } end + if name == "etc_hubcommands" then return { add = function( _cmd, fn ) _onbmsg = fn; return true end } end + return nil + end, +} + +local LANG_EN = { msg1 = " | Command: [+!#]", msg2 = " | used by: " } +local LANG_DE = { msg1 = " | Befehl: [+!#]", msg2 = " | benutzt von: " } + +---------------------------------------------------------------------- +-- helpers +---------------------------------------------------------------------- +local function load_plugin( lang ) + _active_lang = lang + _listeners, _onbmsg, _http = { }, nil, nil + assert( loadfile( "scripts/etc_cmdlog.lua" ) )( ) + -- fire onStart so hubcmd.add captures the show handler + if _listeners[ "onStart" ] then _listeners[ "onStart" ]( ) end +end + +local function make_user( nick, level ) + return { + level = function( ) return level or 100 end, + nick = function( ) return nick end, + reply = function( _, text ) _last_reply = text end, + } +end + +-- fire onBroadcast with a "+cmd args" line +local function fire_write( cmdline ) + _listeners[ "onBroadcast" ]( make_user( "writer", 100 ), { }, cmdline ) +end + +-- fire the captured show handler +local function fire_show( user ) + _last_reply = nil + return pcall( _onbmsg, user, { }, "show", "+cmdlog show" ) +end + +---------------------------------------------------------------------- +-- Case 1: THE BUG. Write under English, switch hub to German, show must +-- render German labels. Fails on v1.4 (labels baked English at write). +---------------------------------------------------------------------- +_fs = { } +load_plugin( LANG_EN ) +fire_write( "+accinfo" ) +load_plugin( LANG_DE ) -- language change; log file persists +local okrun = fire_show( make_user( "op", 100 ) ) +ok( "show does not crash after language switch", okrun, _last_reply ) +ok( "entry written under en renders German label msg1 after switch to de", + contains( _last_reply, "Befehl: [+!#]accinfo" ), _last_reply ) +ok( "entry renders German label msg2 after switch to de", + contains( _last_reply, "benutzt von: writer" ), _last_reply ) +ok( "no stale English label leaks through", + not contains( _last_reply, "Command:" ) and not contains( _last_reply, "used by:" ), _last_reply ) +-- freeze the exact rendered layout: " [ ts ]" wrapper + label spacing + +-- the single cmd/args space (guards against a future off-by-one that a +-- loose substring check would miss). args is empty here. +local expected_entry = " [ 2026-07-18 / 12:00:00 ]" .. LANG_DE.msg1 .. "accinfo" .. " " .. LANG_DE.msg2 .. "writer" +ok( "rendered entry is byte-exact (spacing frozen)", contains( _last_reply, expected_entry ), expected_entry ) + +---------------------------------------------------------------------- +-- Case 2: migration. An old baked (v1.4) line has no delimiter and must +-- render as-is (frozen language) without crashing or being dropped. +---------------------------------------------------------------------- +_fs = { [ "log/cmd.log" ] = " [ 2026-01-01 / 00:00:00 ] | Command: [+!#]oldcmd | used by: OldUser\n" } +load_plugin( LANG_DE ) +okrun = fire_show( make_user( "op", 100 ) ) +ok( "old baked line: show does not crash", okrun, _last_reply ) +ok( "old baked line rendered as-is (frozen English preserved)", + contains( _last_reply, "Command: [+!#]oldcmd" ) and contains( _last_reply, "used by: OldUser" ), _last_reply ) + +---------------------------------------------------------------------- +-- Case 3: mixed file. Old baked line + a new entry: old stays frozen, +-- new renders in the current (German) language. +---------------------------------------------------------------------- +_fs = { [ "log/cmd.log" ] = " [ 2026-01-01 / 00:00:00 ] | Command: [+!#]oldcmd | used by: OldUser\n" } +load_plugin( LANG_DE ) +fire_write( "+accinfo now" ) +okrun = fire_show( make_user( "op", 100 ) ) +ok( "mixed file: show does not crash", okrun, _last_reply ) +ok( "mixed file: old line stays English", contains( _last_reply, "Command: [+!#]oldcmd" ), _last_reply ) +ok( "mixed file: new line is German with its args", contains( _last_reply, "Befehl: [+!#]accinfo now" ), _last_reply ) + +---------------------------------------------------------------------- +-- Case 4: redacted args. A command in redact_args stores , +-- never the raw argument, and shows it re-localized. +---------------------------------------------------------------------- +_fs = { } +load_plugin( LANG_DE ) +fire_write( "+setpass hunter2secret" ) +fire_show( make_user( "op", 100 ) ) +ok( "redacted command never stores the raw secret", not contains( _fs[ "log/cmd.log" ], "hunter2secret" ), _fs[ "log/cmd.log" ] ) +ok( "redacted command shows ", contains( _last_reply, "" ), _last_reply ) + +---------------------------------------------------------------------- +-- Case 5: control-byte hardening. A newline / delimiter in args is +-- stripped, so the stored file stays one line per entry and no false +-- field boundary is created. +---------------------------------------------------------------------- +_fs = { } +load_plugin( LANG_DE ) +fire_write( "+accinfo a\nb\31c" ) -- newline + a raw US delimiter in args +-- the stored file must be exactly one line (one trailing newline) +local nl_count = select( 2, _fs[ "log/cmd.log" ]:gsub( "\n", "" ) ) +ok( "control bytes in args do not add extra lines", nl_count == 1, "newlines=" .. tostring( nl_count ) ) +okrun = fire_show( make_user( "op", 100 ) ) +ok( "control-byte entry: show does not crash", okrun, _last_reply ) +ok( "control bytes replaced, args still one field", contains( _last_reply, "Befehl: [+!#]accinfo a?b?c" ), _last_reply ) + +---------------------------------------------------------------------- +-- Case 6: HTTP path re-localizes too (same render as show). +---------------------------------------------------------------------- +_fs = { } +load_plugin( LANG_EN ) +fire_write( "+accinfo" ) +load_plugin( LANG_DE ) +local res = _http( { query = { } } ) +ok( "HTTP handler returns 200", res and res.status == 200, res and res.status ) +ok( "HTTP line re-localized to German", res and contains( res.data.lines[ 1 ], "Befehl: [+!#]accinfo" ), res and res.data.lines[ 1 ] ) + +---------------------------------------------------------------------- +io.write( string.format( "\n%d/%d checks passed\n", checks - failures, checks ) ) +if failures > 0 then io.write( "FAIL etc_cmdlog_test\n" ); os.exit( 1 ) end +io.write( "OK etc_cmdlog_test\n" )