Stop building terminal debug messages on hot paths - #1039
Conversation
|
Independent re-verification of the suite claim, by the reviewer rather than the branch author:
Same failure, same seed, with and without the branch; it passes in isolation on both trees. So the net effect of this branch on the package is +1 test (the new causality test) and no change in failures. The "0 failures" line in the body was a single lucky run under lighter load. |
Unified Regression Test ResultsWorkflow: Unified Regression Testing Performance ResultsFound 1 performance result(s) Memory ResultsFound 3 memory result(s) Targets
|
Adversarial Review: PR #1039 (mode-log-lazy)Three personas ran independently over this diff (Saboteur, New Hire, Security Auditor), each with its own worktree probes. Severity promoted one level where two or more personas landed on the same defect. CRITICAL
HIGH
MEDIUM
LOW
Cross-persona overlaps
Verdict: BLOCKBefore merge: lazify or delete the eight DCS/sixel sites and re-measure that class the way the PR measured CSI h/l; teach |
log/3 interpolated its `msg` argument whenever a context was given, so
`Log.debug(fn -> ... end, %{...})` raised Protocol.UndefinedError before
any level check - String.Chars is not implemented for Function. The
fun form is now the required shape on per-byte paths, and adding a
context map to one of those call sites is the obvious next edit, so
that combination has to work.
The context is folded in by wrapping the fun rather than by forcing it:
Logger.bare_log/2 evaluates a fun only when the level is enabled, so
neither the interpolation nor inspect(context) runs when logging is off.
debug/1 gains a @doc/@SPEC stating that a zero-arity fun is accepted
and is the required form on hot paths, and the moduledoc Usage block
shows it; until now the only description of the convention was a
comment in a test file.
execute_dcs_command/5 was the clause the earlier pass missed: /4 got a zero-arity fun, but /5 is the arity the parser reaches (via DCSPassthroughMaybeSTState), and it formatted inspect(data_string) - an unbounded DCS payload - on every terminated DCS sequence at every level. dcs_handler built a message per sixel pixel inside the blit reduce, and still dumped pixel_buffer and palette eagerly, both directly in log_sixel_debug_info and inside inspect(updated_sixel_state). The two whole-map dumps are deleted (the success path is already traced by the "blit completed" line, and a pixel map has no diagnostic value in a log line); the per-pixel coordinate trace is deferred, matching the colour lookup line right below it. sixel_parser's parse/2 entry and handle_data_character both inspected a palette entry ahead of their already-deferred siblings; parse/2 recurses per byte, so that ran per input byte.
The guard only rejected built messages containing "mode_log_probe", but
the two most expensive messages this path used to build - the
mode_manager struct and the whole {:ok, emulator} result - named no
mode, so reintroducing either one passed. It now rejects any
already-built debug-level message on the traced path; other levels are
left alone because they are not per-byte.
The drain was also unsound: trace messages are not ordered against the
task's reply, so a `receive ... after 0` straight after Task.await
could see a prefix of them - an empty drain satisfied the assertion,
and a partial one failed the is_function/1 check at random.
erlang:trace_delivered/1 is the fence, so no sleep is involved.
Verified by temporarily adding an eager interpolated Log.debug to
ModeManager.set_mode/3: the test fails naming the built message, and
passes once it is removed.
handle_cr/1 and the pending-wrap helper read the cursor position into a variable and then interpolated it, so the read happened at every log level. With emulator.cursor held as a pid that read is a synchronous GenServer.call: three per CR byte, seven across a wrap, all but one of them existing only for a trace. Moving the call into the macro argument leaves the lookups move_to/3 actually needs (measured with the Logger at :info: 3 -> 1 for a plain CR, 7 -> 3 across a wrap). Two logs echoed input they should not: the CSI intermediate state inspected the whole remaining chunk, which can carry an OSC 52 clipboard payload, and CoreHandler did the same with the parser's leftovers. Both now report a byte count. In the other direction, the DECRQSS selector, the malformed OSC and the sixel pc/pn params are bounded and not secret, so those warnings name what was rejected again instead of saying nothing at WARNING level; the DECRQSS and OSC cases log a bounded prefix so an oversized payload still cannot reach the log. A sixel pixel with no palette entry is traced rather than silently dropped. Log.debug alternated with Logger.debug line by line in single functions, with the rule written nowhere. Every module here that can require Logger now uses the macros for plain level calls, and the moduledoc states the rule. The fun-accepting clauses added for lazy rendering had no caller outside their own test, so they and the test go. config/runtime.exs accepts "warn" again: it maps TERMINAL_LOG_LEVEL onto the node-wide Logger level and rejected a spelling Logger still takes, turning a harmless setting into a boot-time ArgumentError. The comment now says the level is node-wide. dev.exs and test.exs drop the dead :raxol, :terminal, :log_level key that nothing reads. The mode_manager test asserted the exact debug string, so reintroducing eager interpolation passed it. It now traces Kernel.inspect/1 and String.Chars.to_string/1 calls attributed to ModeManager while that module's level is disabled, which fails on an eager message and pins no wording. The DECRQSS redaction assertion no longer hides behind `if log != ""`.
64c513f to
d54bba1
Compare
#1056 edited mix.lock in place to bump mox. That is enough for Mix to re-resolve the whole graph on the next deps.get, and the resolution moves phoenix_template 1.0.4 -> 1.1.0 (both satisfy the ~> 1.0 that phoenix and phoenix_live_view declare). The lock did not record it, so the Setup & Cache job's `mix deps.get --check-locked` exits 1 on master and on every branch cut from it: ** (Mix) Your mix.lock is out of date and must be updated without the --check-locked flag Run 35653xxxxx on master (d8a8cc1) is red for exactly this, which turns CI Status red on every open PR. Lock regenerated by mix, no manual edit. (cherry picked from commit d08efc1)
packages/raxol_symphony and packages/raxol_telegram resolve phoenix_template forward for the same reason the root lock does, and their Package Tests jobs fail at `Compile package` before running a test. The other seven locks carrying phoenix_template resolve to the pinned 1.0.4 and are left alone. (cherry picked from commit 8a829db)
Summary
Makes disabled debug logging cheap without changing terminal mode semantics, and prevents control payloads from reaching logs as raw terminal bytes.
Loggermacros on hot terminal paths so interpolation is skipped below the active level.Raxol.Core.Runtime.Loghelpers.ModeManagerclause behavior intact.:infoin production;TERMINAL_LOG_LEVELuses an explicit validated allowlist.Manual testing
mix format --check-formatted