fix: bound and throttle mobile channel logging #26

graham · 2026-09-14T23:28:27-05:00

graham commented

2026-09-14 23:28:27 -05:00

Fixes W9 from bugs.md.

per-frame inspect(payload) logs removed entirely — handlers log only the event name, so hostile frames can neither flood logs nor inject log content
the remaining receive logs are demoted to debug and moved inside the rate limiter, so denied frames cost no log line
unsubscribe and unsubscribe_callsign now draw on a dedicated generous bucket (120/min), bounding the unthrottled SpatialPubSub churn
two regression tests exhaust each unsubscribe bucket and assert the rate-limit error reply

Verification: focused channel tests passed (62), full suite passed (2237), mix credo --strict, and commit hooks including Dialyzer passed.

Fixes W9 from bugs.md. - per-frame `inspect(payload)` logs removed entirely — handlers log only the event name, so hostile frames can neither flood logs nor inject log content - the remaining receive logs are demoted to `debug` and moved inside the rate limiter, so denied frames cost no log line - `unsubscribe` and `unsubscribe_callsign` now draw on a dedicated generous bucket (120/min), bounding the unthrottled SpatialPubSub churn - two regression tests exhaust each unsubscribe bucket and assert the rate-limit error reply Verification: focused channel tests passed (62), full suite passed (2237), `mix credo --strict`, and commit hooks including Dialyzer passed.

graham added 1 commit

2026-09-14 23:28:27 -05:00

fix: bound and throttle mobile channel logging

Elixir CI / Dialyzer (pull_request) Successful in 39s

Details

Elixir CI / Build and test (pull_request) Successful in 1m41s

Details

Elixir CI / Build and Push Docker Image (pull_request) Has been skipped

Details

skippy-bot/review Skippy review: 1 blocking finding open — see the PR thread

Details

e8f914fac6

skippy-bot reviewed

2026-09-14 23:30:26 -05:00

skippy-bot left a comment

🤖 Skippy PR review

2 findings — 1 blocking before merge.

Severity	Location	Issue
🟡 Warning	`lib/aprsme_web/channels/mobile_channel.ex:154`	Denied frames still cost a log line — one per frame, unbounded
🔵 Suggestion	`lib/aprsme_web/channels/mobile_channel.ex:71`	Unsubscribe bucket is per-IP, and burns a token when there is nothing to release

First review, full diff read (2 files, +76/-34); read-only, nothing executed.

_{Reviewed e8f914fac673. Comment skippy review to re-run.}

### 🤖 Skippy PR review **2 findings** — 1 blocking before merge. | Severity | Location | Issue | | --- | --- | --- | | 🟡 Warning | `lib/aprsme_web/channels/mobile_channel.ex:154` | Denied frames still cost a log line — one per frame, unbounded | | 🔵 Suggestion | `lib/aprsme_web/channels/mobile_channel.ex:71` | Unsubscribe bucket is per-IP, and burns a token when there is nothing to release | First review, full diff read (2 files, +76/-34); read-only, nothing executed. Reviewed `e8f914fac673`. Comment `skippy review` to re-run.

lib/aprsme_web/channels/mobile_channel.ex Outdated

					
				@ -68,0 +68,4 @@

				  # Unsubscribes are cheap but touch the SpatialPubSub GenServer; a generous

				  # dedicated bucket keeps a spamming client from monopolising it while never

				  # inconveniencing a real one.

				  @unsubscribe_limit 120

🔵 Suggestion — Unsubscribe bucket is per-IP, and burns a token when there is nothing to release

@unsubscribe_limit is enforced through check_rate_limit/3, whose key is "mobile_channel:<op>:<peer_ip>" (~line 393) — the bucket is per IP, not per socket, despite the "Per-socket rate limits" docstring. So the "never inconveniencing a real one" 120/min is shared by every client behind one NAT/CGNAT address (and unsubscribe also charges a token when subscribed is already false, so an idle client retrying burns the shared budget it later needs). When it does bite, the client gets a hard :error reply from a handler that previously always replied :ok, and a client that doesn't retry keeps its SpatialPubSub registration and packet stream alive until the socket closes.

Cheapest fix: move check_rate_limit inside the if socket.assigns[:subscribed] && socket.assigns[:bounds] / if socket.assigns[:tracked_callsign] branches so only real releases are throttled, and consider keying on the channel process rather than the peer IP.

**🔵 Suggestion — Unsubscribe bucket is per-IP, and burns a token when there is nothing to release** `@unsubscribe_limit` is enforced through `check_rate_limit/3`, whose key is `"mobile_channel:<op>:<peer_ip>"` (~line 393) — the bucket is per **IP**, not per socket, despite the "Per-socket rate limits" docstring. So the "never inconveniencing a real one" 120/min is shared by every client behind one NAT/CGNAT address (and `unsubscribe` also charges a token when `subscribed` is already false, so an idle client retrying burns the shared budget it later needs). When it does bite, the client gets a hard `:error` reply from a handler that previously always replied `:ok`, and a client that doesn't retry keeps its SpatialPubSub registration and packet stream alive until the socket closes. Cheapest fix: move `check_rate_limit` inside the `if socket.assigns[:subscribed] && socket.assigns[:bounds]` / `if socket.assigns[:tracked_callsign]` branches so only real releases are throttled, and consider keying on the channel process rather than the peer IP.

skippy-bot marked this conversation as resolved

lib/aprsme_web/channels/mobile_channel.ex Outdated

					
				@ -145,2 +153,2 @@

				  def handle_in("unsubscribe", payload, socket) do

				    Logger.info("Mobile websocket received unsubscribe: #{inspect(payload)}")

				  def handle_in("unsubscribe", _payload, socket) do

				    with :ok <- check_rate_limit(socket, "unsubscribe", @unsubscribe_limit) do

🟡 Warning — Denied frames still cost a log line — one per frame, unbounded

The comment above subscribe_bounds says a denied frame costs no log line, but the deny branch of check_rate_limit/3 (this file, ~line 401) logs Logger.warning("Mobile channel rate-limited op=...") on every denial with no dedupe or sampling. Before this patch unsubscribe had no limiter, so those frames were silent; now a client looping push("unsubscribe", %{}) gets 120 allowed frames and then one warning line per frame at line rate — exactly the log-flood W9 was meant to close. config/prod.exs runs level: :info, so demoting the receive logs bought nothing on this path: allow = silent, deny = one line per frame forever.

Fix: keep the reply, lose the per-frame line — e.g. Logger.debug in the deny branch plus a :telemetry.execute([:aprsme, :mobile_channel, :rate_limited], %{count: 1}, %{op: op}) counter, or log only on the transition into denial.

**🟡 Warning — Denied frames still cost a log line — one per frame, unbounded** The comment above `subscribe_bounds` says a denied frame costs no log line, but the deny branch of `check_rate_limit/3` (this file, ~line 401) logs `Logger.warning("Mobile channel rate-limited op=...")` on **every** denial with no dedupe or sampling. Before this patch `unsubscribe` had no limiter, so those frames were silent; now a client looping `push("unsubscribe", %{})` gets 120 allowed frames and then one warning line per frame at line rate — exactly the log-flood W9 was meant to close. `config/prod.exs` runs `level: :info`, so demoting the receive logs bought nothing on this path: allow = silent, deny = one line per frame forever. Fix: keep the reply, lose the per-frame line — e.g. `Logger.debug` in the deny branch plus a `:telemetry.execute([:aprsme, :mobile_channel, :rate_limited], %{count: 1}, %{op: op})` counter, or log only on the transition into denial.

skippy-bot marked this conversation as resolved

graham added 1 commit

2026-09-15 11:34:52 -05:00

fix: no log line per denied frame, charge unsubscribe budget on release only

Elixir CI / Build and test (pull_request) Failing after 57s

Details

skippy-bot/review Skippy review: 1 blocking finding open — see the PR thread

Details

Elixir CI / Dialyzer (pull_request) Successful in 2m56s

Details

Elixir CI / Build and Push Docker Image (pull_request) Has been skipped

Details

23fbcd25b5

skippy-bot reviewed

2026-09-15 11:36:02 -05:00

skippy-bot left a comment

🤖 Skippy PR review

1 finding — 1 blocking before merge.

Severity	Location	Issue
🟠 High	`lib/aprsme_web/channels/mobile_channel.ex:158`	Charge-only-on-release breaks both unsubscribe regression tests (suite is red at this head)

Resolved both earlier findings (deny branch no longer logs per frame; unsubscribe only charges when it releases). The reorder is correct, but it leaves this PR's own unsubscribe tests asserting behaviour that no longer exists, so the suite is red at this head.

_{Reviewed 23fbcd25b5b0. Comment skippy review to re-run.}

### 🤖 Skippy PR review **1 finding** — 1 blocking before merge. | Severity | Location | Issue | | --- | --- | --- | | 🟠 High | `lib/aprsme_web/channels/mobile_channel.ex:158` | Charge-only-on-release breaks both unsubscribe regression tests (suite is red at this head) | Resolved both earlier findings (deny branch no longer logs per frame; unsubscribe only charges when it releases). The reorder is correct, but it leaves this PR's own unsubscribe tests asserting behaviour that no longer exists, so the suite is red at this head. Reviewed `23fbcd25b5b0`. Comment `skippy review` to re-run.

lib/aprsme_web/channels/mobile_channel.ex Outdated

					
				@ -148,3 +157,2 @@

				    if socket.assigns[:subscribed] && socket.assigns[:bounds] do

				      Aprsme.SpatialPubSub.unregister_client(socket.assigns.client_id)

				      Phoenix.PubSub.unsubscribe(Aprsme.PubSub, "spatial:subscriber:#{socket.assigns.client_id}")

				      with :ok <- check_rate_limit(socket, "unsubscribe", @unsubscribe_limit) do

🟠 High — Charge-only-on-release breaks both unsubscribe regression tests (suite is red at this head)

The reorder itself is correct, but it invalidates the two regression tests this PR added, and this commit did not touch the test file, so test/aprsme_web/channels/mobile_channel_test.exs fails at 23fbcd25.

Test at test/aprsme_web/channels/mobile_channel_test.exs:931-934 (unsubscribe): after subscribe_bounds plus one real unsubscribe, subscribed is false, so the 120 pushes in the loop all take the else branch (line 171), charge nothing, and reply {:ok, %{message: "Not subscribed"}}. The final assert_reply refused, :error can never be satisfied.

Test at :938-943 (unsubscribe_callsign): join/3 (line 102) never sets tracked_callsign, so all 121 pushes hit the else branch and the 122nd still replies {:ok, %{message: "Not tracking any callsign"}} instead of the asserted :error.

Both passed at e8f914fa only because the pre-reorder check_rate_limit ran before the if, i.e. the tests assert exactly the behaviour this commit removed.

Fix: charge the bucket directly instead of trying to exhaust it through frames (the setup already hands you peer_ip, line 61):

for _ <- 1..120, do: Aprsme.RateLimiter.hit("mobile_channel:unsubscribe:#{peer_ip}", 60_000, 120)

ref = push(socket, "subscribe_bounds", %{"north" => 33.2, "south" => 33.0, "east" => -96.0, "west" => -96.2})
assert_reply ref, :ok, _

ref = push(socket, "unsubscribe", %{})
assert_reply ref, :error, %{message: "Rate limit exceeded; retry later"}

Driving it through frames cannot work regardless: subscribe_bounds is capped at 30/min, so you cannot re-arm 121 times inside one window. Worth adding the complementary assertion that an idle retry is free (many unsubscribe pushes with nothing subscribed all reply :ok). The PR's "62 focused tests passed" predates this commit.

**🟠 High — Charge-only-on-release breaks both unsubscribe regression tests (suite is red at this head)** The reorder itself is correct, but it invalidates the two regression tests this PR added, and this commit did not touch the test file, so `test/aprsme_web/channels/mobile_channel_test.exs` fails at `23fbcd25`. **Test at `test/aprsme_web/channels/mobile_channel_test.exs:931-934`** (unsubscribe): after `subscribe_bounds` plus one real `unsubscribe`, `subscribed` is `false`, so the 120 pushes in the loop all take the `else` branch (line 171), charge nothing, and reply `{:ok, %{message: "Not subscribed"}}`. The final `assert_reply refused, :error` can never be satisfied. **Test at `:938-943`** (unsubscribe_callsign): `join/3` (line 102) never sets `tracked_callsign`, so all 121 pushes hit the `else` branch and the 122nd still replies `{:ok, %{message: "Not tracking any callsign"}}` instead of the asserted `:error`. Both passed at `e8f914fa` only because the pre-reorder `check_rate_limit` ran *before* the `if`, i.e. the tests assert exactly the behaviour this commit removed. Fix: charge the bucket directly instead of trying to exhaust it through frames (the setup already hands you `peer_ip`, line 61): ```elixir for _ <- 1..120, do: Aprsme.RateLimiter.hit("mobile_channel:unsubscribe:#{peer_ip}", 60_000, 120) ref = push(socket, "subscribe_bounds", %{"north" => 33.2, "south" => 33.0, "east" => -96.0, "west" => -96.2}) assert_reply ref, :ok, _ ref = push(socket, "unsubscribe", %{}) assert_reply ref, :error, %{message: "Rate limit exceeded; retry later"} ``` Driving it through frames cannot work regardless: `subscribe_bounds` is capped at 30/min, so you cannot re-arm 121 times inside one window. Worth adding the complementary assertion that an idle retry is free (many `unsubscribe` pushes with nothing subscribed all reply `:ok`). The PR's "62 focused tests passed" predates this commit.

skippy-bot marked this conversation as resolved

graham force-pushed fix/w9-mobile-channel-logging from 23fbcd25b5

Elixir CI / Build and test (pull_request) Failing after 57s

Details

skippy-bot/review Skippy review: 1 blocking finding open — see the PR thread

Details

Elixir CI / Dialyzer (pull_request) Successful in 2m56s

Details

Elixir CI / Build and Push Docker Image (pull_request) Has been skipped

Details

to 8dbf67abc1

Elixir CI / Build and test (pull_request) Successful in 55s

Details

Elixir CI / Dialyzer (pull_request) Successful in 2m49s

Details

Elixir CI / Build and Push Docker Image (pull_request) Has been skipped

Details

skippy-bot/review Skippy review: clean — 1 non-blocking note open

Details

2026-09-15 19:14:54 -05:00

Compare

skippy-bot reviewed

2026-09-15 19:18:28 -05:00

skippy-bot left a comment

🤖 Skippy PR review

1 finding — none blocking.

Severity	Location	Issue
🔵 Suggestion	`lib/aprsme_web/channels/mobile_channel.ex:431`	The replacement signal for the silenced deny log is a no-op in prod

Resolved the earlier High: both unsubscribe regression tests are rewritten at 8dbf67ab to charge the bucket directly (see the new exhaust_rate_limit/2 helper) and now assert the charge-only-on-release rule instead of the removed behaviour. Branch was rebased, so this re-read the full PR diff.

_{Reviewed 8dbf67abc1b5. Comment skippy review to re-run.}

### 🤖 Skippy PR review **1 finding** — none blocking. | Severity | Location | Issue | | --- | --- | --- | | 🔵 Suggestion | `lib/aprsme_web/channels/mobile_channel.ex:431` | The replacement signal for the silenced deny log is a no-op in prod | Resolved the earlier High: both unsubscribe regression tests are rewritten at `8dbf67ab` to charge the bucket directly (see the new `exhaust_rate_limit/2` helper) and now assert the charge-only-on-release rule instead of the removed behaviour. Branch was rebased, so this re-read the full PR diff. Reviewed `8dbf67abc1b5`. Comment `skippy review` to re-run.

lib/aprsme_web/channels/mobile_channel.ex Outdated

					
				@ -412,0 +428,4 @@

				        Logger.debug("Mobile channel rate-limited op=#{op} client=#{inspect(self())}")

				        :telemetry.execute(

				          [:aprsme, :mobile_channel, :rate_limited],

🔵 Suggestion — The replacement signal for the silenced deny log is a no-op in prod

The deny branch now logs at debug (line 428) and config/prod.exs:39 runs level: :info, so the replacement signal is [:aprsme, :mobile_channel, :rate_limited] (line 431) - and nothing in the app is attached to it. It is the only [:aprsme, ...] event emitted without a PromEx counter: payload_metrics/0 registers [:aprsme, :payload, :rejected], mobile_metrics/0 registers [:aprsme, :mobile, :buffer_overflow], and this event appears nowhere but this line. :telemetry.execute/3 with no handler is a no-op, so a refused frame now costs no log line and no metric, and the first sign of a client stuck against the per-IP bucket (shared behind CGNAT) is its own error reply - including the new hard :error on unsubscribe/unsubscribe_callsign. Fix: register it next to mobile_metrics/0 in lib/aprsme/prom_ex/plugins/aprsme.ex, which already has the shape:

counter(
  [:aprsme, :mobile_channel, :rate_limited, :total],
  event_name: [:aprsme, :mobile_channel, :rate_limited],
  measurement: :count,
  description: "Mobile channel frames refused by the per-IP rate limiter",
  tags: [:op]
)

**🔵 Suggestion — The replacement signal for the silenced deny log is a no-op in prod** The deny branch now logs at `debug` (line 428) and `config/prod.exs:39` runs `level: :info`, so the replacement signal is `[:aprsme, :mobile_channel, :rate_limited]` (line 431) - and nothing in the app is attached to it. It is the only `[:aprsme, ...]` event emitted without a PromEx counter: `payload_metrics/0` registers `[:aprsme, :payload, :rejected]`, `mobile_metrics/0` registers `[:aprsme, :mobile, :buffer_overflow]`, and this event appears nowhere but this line. `:telemetry.execute/3` with no handler is a no-op, so a refused frame now costs no log line *and* no metric, and the first sign of a client stuck against the per-IP bucket (shared behind CGNAT) is its own error reply - including the new hard `:error` on `unsubscribe`/`unsubscribe_callsign`. Fix: register it next to `mobile_metrics/0` in `lib/aprsme/prom_ex/plugins/aprsme.ex`, which already has the shape: ```elixir counter( [:aprsme, :mobile_channel, :rate_limited, :total], event_name: [:aprsme, :mobile_channel, :rate_limited], measurement: :count, description: "Mobile channel frames refused by the per-IP rate limiter", tags: [:op] ) ```

skippy-bot marked this conversation as resolved

graham force-pushed fix/w9-mobile-channel-logging from 8dbf67abc1

Elixir CI / Build and test (pull_request) Successful in 55s

Details

Elixir CI / Dialyzer (pull_request) Successful in 2m49s

Details

Elixir CI / Build and Push Docker Image (pull_request) Has been skipped

Details

skippy-bot/review Skippy review: clean — 1 non-blocking note open

Details

to 94b38af6cd

Elixir CI / Build and test (pull_request) Successful in 56s

Details

Elixir CI / Dialyzer (pull_request) Successful in 2m57s

Details

Elixir CI / Build and Push Docker Image (pull_request) Has been skipped

Details

skippy-bot/review Skippy review: clean — no open findings

Details

2026-09-15 19:30:37 -05:00

Compare

skippy-bot commented

2026-09-15 19:31:35 -05:00

First-time contributor

Resolved 1 of 1 open finding: [:aprsme, :mobile_channel, :rate_limited] is now registered as a PromEx counter with bounded [:op] tags in mobile_metrics/0 (lib/aprsme/prom_ex/plugins/aprsme.ex:199), so the silenced deny path has a prod-visible signal again, and the new plugin test asserts the metric name.

Branch was rebased, so this re-read the full PR diff rather than an incremental range: beyond that counter and its test, nothing changed from 8dbf67ab. No new findings, nothing left open.

Resolved 1 of 1 open finding: `[:aprsme, :mobile_channel, :rate_limited]` is now registered as a PromEx counter with bounded `[:op]` tags in `mobile_metrics/0` (`lib/aprsme/prom_ex/plugins/aprsme.ex:199`), so the silenced deny path has a prod-visible signal again, and the new plugin test asserts the metric name. Branch was rebased, so this re-read the full PR diff rather than an incremental range: beyond that counter and its test, nothing changed from `8dbf67ab`. No new findings, nothing left open.

graham commented

2026-09-15 19:34:21 -05:00

skippy review

graham merged commit 84054458ae into main

2026-09-16 08:43:11 -05:00

graham deleted branch fix/w9-mobile-channel-logging

2026-09-16 08:43:11 -05:00

graham referenced this pull request from a commit

2026-09-16 08:43:11 -05:00

fix: bound and throttle mobile channel logging (#26)

Sign in to join this conversation.

No reviewers