Skip to content

fix(app): rate-limit repeated command error logging - #7372

Open
lbellows wants to merge 1 commit into
modrinth:mainfrom
lbellows:fix/rate-limit-command-error-logging
Open

fix(app): rate-limit repeated command error logging#7372
lbellows wants to merge 1 commit into
modrinth:mainfrom
lbellows:fix/rate-limit-command-error-logging

Conversation

@lbellows

Copy link
Copy Markdown

Closes part of #7371.

Problem

A failing Tauri command is retried by the frontend, and the error is logged from inside Serialize for TheseusSerializableError (apps/app/src/api/mod.rs). So one persistent fault turns into an unbounded log storm rather than a single message.

On the machine in #7371 a saturated SQLite pool produced, measured from the launcher logs:

  • ~4,000–5,000 identical lines per second
  • 338,142 errors inside a single two-minute window
  • a 189 MB session log; 1.1 GB of launcher_logs/ total (it gzips 43:1, which is itself a measure of how repetitive it is)
  • 1,390,704 copies of one message across the logs on that install

Pushing that many error events into the WebView drives WebKitWebProcess to 11–15 GiB until it is OOM-killed or crashes. Because the Tauri frame outlives the renderer, the user is left with a grey window that still has a working titlebar — which is how this presents in the wild, and why it reads as a rendering bug rather than a logging one.

What this changes

Deduplicate by rendered error message:

  • first occurrence logs immediately, exactly as before
  • subsequent identical messages log at most once per 5 seconds, reporting a suppressed count of what was dropped
  • output is byte-for-byte unchanged when nothing was suppressed, so existing log greps keep working

Two details to keep the fix from becoming its own problem:

  • the suppression table is capped at 256 entries with least-recently-logged eviction, so it cannot grow without bound
  • hashing goes through a Hasher sink implementing fmt::Write rather than allocating a String, so the common (suppressed) path does no allocation

Scope

This is deliberately narrow: it fixes the amplifier, not the underlying fault. The root cause in #7371 is a separate file-descriptor/connection leak — that install had 1,774 open fds on app.db after under four hours, with exactly 100 app.db-wal handles matching max_connections(100) in packages/app-lib/src/state/db.rs. I have not diagnosed that half and am not touching it here.

I think this is worth doing on its own merits regardless of that: any fault that makes a frequently-retried command fail will take the renderer down through this path, and rate-limiting is the general defence.

Testing

apps/app does not currently build on my machine (no webkit2gtk dev headers), so I could not run the crate's own test suite. What I did verify, on rustc 1.95.0 / edition 2024, matching rust-toolchain.toml:

  • the pure suppression logic and all four logging arms were extracted verbatim into a scratch crate with tracing as its only dependency, and 7 unit tests pass — first-occurrence, suppression counting and backlog reporting, independence of distinct messages, table bounding under 4× overload, hash stability, the LazyLock/Mutex wrapper, and reachability of every macro arm
  • four of those tests ship in this PR as #[cfg(test)] mod tests against should_log_in, which is split out from should_log precisely so it is testable without the global table
  • rustfmt --edition 2024 --config max_width=80 --check is clean

So the logic and syntax are verified; the integration against the real theseus::Error is not, and I would appreciate CI confirming it.

Note on the interval

REPEAT_INTERVAL of 5 seconds is a judgement call. It is short enough that a genuinely recurring problem stays visible in the logs and long enough to cut a 5,000/sec storm to 0.2/sec. Happy to change it, or to make it scale with observed rate, if you would rather.

A failing Tauri command is retried by the frontend, so one persistent fault
can log the same error thousands of times per second. Observed on Linux with
a saturated SQLite pool: ~4,000-5,000 identical lines/sec, 338k errors in a
two-minute window, and 189 MB single-session log files. Feeding that volume
of error events into the WebView drives WebKitWebProcess to 11-15 GiB until
it is OOM-killed or crashes, leaving the window grey but still closable
because the Tauri frame outlives the renderer.

Deduplicate by error message: log the first occurrence immediately, then at
most once per 5 seconds per distinct message, reporting how many identical
occurrences were dropped. Output is unchanged when nothing was suppressed.

The suppression table is capped at 256 entries with least-recently-logged
eviction, and hashing goes through a Hasher sink rather than allocating a
String, so the suppressed path stays cheap under a storm.
@github-actions

Copy link
Copy Markdown
Contributor

Pull request changelog

App

Added

Changed

Deprecated

Removed

Fixed

Security

Website

Added

Changed

Deprecated

Removed

Fixed

Security

Hosting

Added

Changed

Deprecated

Removed

Fixed

Security

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Development

Successfully merging this pull request may close these issues.

1 participant