Uh oh!
There was an error while loading. Please reload this page.
Make the fingerprint log mean something - #705
Merged
Merged
Conversation
One reporting app carried 765 `user_agent_mismatch` warnings in a single log, plus `[error] ... possible hijacking attempt` lines after which — in non-strict mode — the request was served anyway. Per-request, unthrottled, naming neither the user nor the session, and doubled: `verify_fingerprint/3` logged, then the web caller logged again with a line that said only "for token" and named no token. That is worse than logging nothing. An error that takes no action and identifies no one teaches people the log is noise, and the lines that would have mattered go with it. Three changes, all about making the level and the content honest: * A user-agent change with the same IP is `:info`, not `:warning`. Browsers rewrite their UA on every update — roughly monthly, for every user — so at warning level this was the bulk of the volume, for something that is almost never an attack and is never acted on. A normally-configured app stops seeing it entirely. * Both-changed picks its level from what actually happens: `:error` when strict mode denies the request, `:warning` when the request is served. "Possible hijacking attempt" at `:error` followed by serving the request is exactly what trains people to ignore `:error`. * Every line names its session — a truncated SHA-256 of the token, since the raw token is a bearer credential and must never reach a log. Eight hex characters is enough to group lines and useless to anyone who steals the file. The duplicate log in `PhoenixKitWeb.Users.Auth` is gone; the surviving line already says what changed, for which session, at the right level. Two mutations checked: restoring the UA warning fails the suite, and always logging `:error` for both-changed fails it twice.
ddon pushed a commit
that referenced
this pull request
Aug 11, 2026
Review docs for all three PRs in dev_docs/pull_requests/2026/. #704 — two bugs on the read-then-write race in `upsert_inapp/3`: * The `update_all` filtered on `uuid` alone, so the unseen/undismissed rule held only in the read. A row dismissed or read in between was refreshed anyway — the update reported success and the event ended up recorded only on a row that will never be shown again. The guard now appears in the write too, which also makes the fallback reachable for the reason it was written. * The fallback posted the replacement row without its dedupe key, so it could never be found again: every later event for that key opened a new row. One lost race turned collapsing off permanently. #705 — the level-follows-consequence rule was applied to one branch of three. Strict mode refuses every mismatch (`PhoenixKitWeb.Users.Auth` answers `{:warning, _}` exactly as it answers `{:error, _}`), so a strict-mode host logging someone out over a browser update recorded it at `:info` — below the default threshold, i.e. not at all. Extracted `log_mismatch/2`; non-strict behaviour is unchanged in all three branches, which the untouched existing tests demonstrate. #703 — the warning was emitted with `IO.warn/1`, which registers a compiler diagnostic and so failed the build on any host using `--warnings-as-errors`, on upgrade, over a mix.exs condition that is not a regression in their code. That contradicted the PR's own guarantee and the rescue guards written to back it up. Now written straight to stderr; pinned by a test asserting no diagnostic is registered. Also updates deps (phoenix 1.8.10, hackney 4.7.3) and corrects the `version/0` doc example, which still claimed "1.3.3". Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
ddon pushed a commit
that referenced
this pull request
Aug 14, 2026
An adversarial review of the notifications-upsert, fingerprint-logging and js-compiler-warning work (PRs #702-#705) confirmed ten findings. All ten are fixed here; the two that needed schema support ride a new migration. Notifications (V170 + code): The dedupe lookup and the unseen-first ordering had no index support — recent_for_user runs on every bell mount and had gone from index-served to fetch-everything-and-sort. V170 adds two indexes: a partial UNIQUE on (recipient_uuid, metadata->>'dedupe_key') over undismissed unseen keyed rows, which serves find_collapsible's exact predicate AND closes the find-then-insert race — two workers inserting the same absent key now trip the constraint, and insert_collapsible retries the find and folds. Pre-existing duplicate unseen rows are folded (all but the newest per key marked dismissed) under the same table lock that creates the index, so nothing slips into the gap. The second index matches order_unseen_first's expression term-for-term. The anticipated constraint trip is not logged as a failure; every other insert error still is. upsert_inapp now honors the notifications_enabled kill switch like create/1 — it is a host-facing entry point, and "off" that quietly did not apply to the newest creation path was not off. Caller metadata is merged FIRST and the reserved keys stamped on top, so a passed-through metadata map can no longer clobber the dedupe_key (silently disabling collapsing) or the display keys; caller keys are normalized to strings so %{notification_text: ...} cannot coexist with the string key and win adapter-order-dependently. find_collapsible gains the catch :exit the project's soft-failure rule requires (a dead pool EXITS, bypassing rescue and crashing the caller the comment promised it would not), and both rescue and catch now log, so a permanent query bug degrading upsert into insert-always is diagnosable. find_collapsible also tie-breaks on uuid below inserted_at's second granularity. The inbox's handle_info whitelist gains :notification_updated — the bell had it, the inbox did not, so an open inbox showed stale rows exactly when upsert refreshed one; a scrape test now holds the whitelist to every event the library broadcasts. Fingerprint logging: The dedup had only landed in fetch_phoenix_kit_current_user; fetch_phoenix_kit_current_scope still carried the old "(scope)" warning and the ":error possible hijacking" line for requests that were then served — and the shipped :phoenix_kit_admin_only pipeline runs BOTH plugs, so a mismatch logged three lines. Verification now runs at most once per request (verdict cached in conn.private, both plugs share it) with no extra logging on any branch. session_label is now THE SAME derivation the sessions UI shows as its token preview (hex of the raw token's first 4 bytes) — the truncated-sha256 label could never match it, so the correlation the comment promised failed every time an operator tried it. JS-compiler warning: warn_missing_js_compiler read Mix.Project.config() of whatever project was compiling, so a module package running its own test suite (its router expands phoenix_kit_routes(), discovery finds its own beam) got the fix-your-mix.exs warning on every compile for a configuration that was correct. The warning is now suppressed when any warned module was compiled from the current project's own source tree — excluding deps/, which sits UNDER cwd; the first cut missed that and the test caught every hex dep reading as locally compiled. And modules_declaring_js_sources gains a catch clause: a throw or exit from a discovered module's js_sources/0 escaped the rescue and failed the host's compile, precisely what the adjacent guarantee promises cannot happen. The expected-schema manifest carries the two V170 indexes hand-declared with definitions and opclasses captured from pg_get_indexdef on a live database (not hand-derived), and chain_hash was restamped over the 36 shipped files — the same treatment the V165..V167 objects received, with the same caveat recorded: verify.exs s7/s8 against a real database is what proves the manifest body, and still requires a pre-squash checkout. Full suite: 3536 tests, 0 failures, database reachable (integration tests ran). The V169 lock-guard and version-headings tests caught two omissions in the first cut of V170 — both fixed, both now covered.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for freeto join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
From the integration report, item #5.
What the log looked like
One app carried 765
user_agent_mismatchwarnings in a single log, plus[error] ... possible hijacking attemptlines after which — in non-strict mode— the request was served anyway.
Per-request, unthrottled, naming neither the user nor the session. And
doubled:
verify_fingerprint/3logged, thenPhoenixKitWeb.Users.Authlogged again with a line that said only
"for token"and named no token.That is worse than logging nothing. An error that takes no action and
identifies no one teaches people the log is noise — and the lines that would
have mattered go out with it.
Three changes, all about making the level and the content honest
A user-agent change with the same IP is
:info. Browsers rewrite their UAon every update, roughly monthly, for every user. At warning level this was the
bulk of the volume, for something that is almost never an attack and is never
acted on. A normally-configured app stops seeing it entirely.
Both-changed picks its level from what actually happens —
:errorwhenstrict mode denies the request,
:warningwhen the request is served. Logging"possible hijacking attempt" at
:errorand then serving the request isprecisely what trains people that
:errormeans nothing here.Every line names its session — a truncated SHA-256 of the token. The raw
token is a bearer credential and must never reach a log; eight hex characters
is enough to group a handful of lines and useless to anyone who steals the
file.
The duplicate log in the web caller is gone. The surviving line already says
what changed, for which session, at the right level.
Testing
Seven tests on what actually reaches the log, including the two cases the
report is about: a UA-only change must not be a warning, and both-changed must
not be an
:errorwhen the request is allowed anyway.Both mutation-tested: restoring the UA warning fails the suite; always logging
:errorfails it twice.Worth noting the suite has to lower
Logger.levelitself — it runs at:warning, which is the whole point of the demotion, and from the outside"logged at info" and "not logged" are the same thing. That's in the setup with
a restore.
256 fingerprint + auth tests pass,
credo --strictclean, compiles with--warnings-as-errors.Not done
The report's fourth suggestion — surfacing genuine both-changed mismatches as
an admin-visible security event in the sessions UI — is a feature, not a
logging fix, and wants its own design. Left for that.
No version bump or CHANGELOG entry.
🤖 Generated with Claude Code
https://claude.ai/code/session_01NTj7hm3fpCTcFvKLRtgppW