Close never waits on the log, the refusal is the door itself, no test leaks a worker
Astra on #20, round 3.
P2, close could hang on a stalled log sink: its diagnostics and the
worker's were direct logger calls. Now only a log pump writes to the
logger; the worker and close hand lines to logf, which never blocks (a
buffered channel, and a count of lines lost when it is full). close
returns within its bound and the worker exits whatever the sink does;
the pump ends with the worker.
Four test apps leaked their mail workers (three newApp calls in
auth_test.go and one in config_test.go never closed). They close in
cleanup now, and both test packages' TestMain fail the run if any
mailQueue worker or pump is still running afterwards.
P2, ?err=refused could be typed by anybody: doorOnRefusal now renders
the door in the refusal's own 403, marked through the request context;
the query no longer selects the refusal sentence.
Tests: TestMailQueueCloseIsBoundedWithAStalledLogger (close in time,
worker gone, goroutines back to baseline once the sink is released)
fails on 7ef08e7 ("close hung on a stalled log sink"); the TestMain leak
check failed with 8 queue goroutines before the cleanups;
TestKeymailRefusalIsTheDoor and the Home-mode test now require the door
in the 403 and no refusal sentence at ?err=refused, and fail on 7ef08e7.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
9 files changed,
+292
−65
AGENTS.md+1 −1internal/slides/app.go+4 −4internal/slides/auth.go+57 −23internal/slides/auth_test.go+9 −3internal/slides/config_test.go+1 −0internal/slides/keymail_home_test.go+18 −6internal/slides/mailqueue.go+94 −11internal/slides/mailqueue_test.go+69 −6internal/slidestest/keymail_signin_test.go+39 −11
CI passed — run details
CI log
=== gate ===
=== rust: fmt
=== rust: clippy
Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.09s
=== wasm: the artifact the host embeds
Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.03s
Finished `release` profile [optimized] target(s) in 0.08s
core/target/wasm32-unknown-unknown/release/slides_core.wasm (1228229 bytes)
=== the embedded wasm must match a fresh build
=== rust: test
Finished `test` profile [unoptimized + debuginfo] target(s) in 0.03s
Running unittests src/lib.rs (core/target/debug/deps/slides_core-929bfceb2edd4a94)
running 30 tests
test check::tests::the_empty_document_passes ... ok
test layout::tests::aside_region_rect ... ok
test layout::tests::default_region_by_kind ... ok
test layout::tests::body_region_rect_narrows_for_an_aside ... ok
test layout::tests::heading_region_rect ... ok
test layout::tests::media_region_rect ... ok
test layout::tests::to_canvas_narrows_body_when_an_aside_is_present ... ok
test markdown::tests::empty_input_is_no_paragraphs_and_lines_keep_blanks ... ok
test markdown::tests::marks_nest_and_links_carry_marks ... ok
test markdown::tests::paragraphs_split_on_blank_lines_and_list_markers ... ok
test markdown::tests::inline_marks ... ok
test layout::tests::to_flow_is_a_no_op_when_already_in_order ... ok
test layout::tests::to_canvas_splits_a_shared_region_equally_and_sets_z_by_index ... ok
test check::tests::an_element_inside_a_paragraph_is_reported ... ok
test layout::tests::to_flow_classifies_by_position_and_kind ... ok
test check::tests::bare_text_at_fragment_level_is_reported ... ok
test schema::tests::an_empty_map_reads_as_a_set_mark ... ok
test check::tests::a_non_paragraph_child_is_reported ... ok
test check::tests::what_the_ops_write_passes ... ok
test check::tests::y_prosemirror_shapes_pass ... ok
test layout::tests::to_flow_orders_y_then_x ... ok
test check::tests::an_unknown_formatting_attribute_is_reported ... ok
test schema::tests::an_href_map_without_a_string_url_reads_as_no_link ... ok
test schema::tests::href_written_as_a_plain_string_still_reads_back ... ok
test schema::tests::href_is_written_as_a_one_key_map_and_reads_back ... ok
test view::tests::malformed_fonts_are_null ... ok
test view::tests::malformed_box_is_null_and_phone_keeps_only_typed_fields ... ok
test view::tests::malformed_background_is_the_default ... ok
test view::tests::assets_are_typed_or_skipped ... ok
test layout::tests::to_flow_keeps_a_concurrent_text_edit ... ok
test result: ok. 30 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
Running tests/no_host_imports.rs (core/target/debug/deps/no_host_imports-184c0d8bf00e14f9)
running 1 test
test no_host_imports ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
Running tests/ops.rs (core/target/debug/deps/ops-256addce27f366d1)
running 12 tests
test ops_are_atomic ... ok
test add_slide_then_view_lists_it ... ok
test add_block_with_markdown_produces_runs ... ok
test remove_block_drops_it_from_columns_children ... ok
test layout_switch_assigns_boxes ... ok
test update_roundtrip ... ok
test columns_children_must_name_blocks_on_the_slide ... ok
test columns_children_have_one_parent_and_no_cycles ... ok
test duplicate_slide_remaps_columns_children ... ok
test move_block_keeps_a_concurrent_text_edit ... ok
test move_slide_keeps_a_concurrent_text_edit ... ok
test remaining_ops_roundtrip ... ok
test result: ok. 12 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s
Doc-tests slides_core
running 0 tests
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
=== rust: fmt (pdf)
=== rust: clippy (pdf)
Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.09s
=== wasm: the pdf artifact the host embeds
Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.03s
Finished `release` profile [optimized] target(s) in 0.07s
core/pdf/target/wasm32-unknown-unknown/release/slides_pdf.wasm (5301002 bytes)
=== the embedded pdf wasm must match a fresh build
=== rust: test (pdf)
Finished `test` profile [unoptimized + debuginfo] target(s) in 0.04s
Running unittests src/lib.rs (core/pdf/target/debug/deps/slides_pdf-891fafaa44f9fd64)
running 0 tests
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
Running tests/no_host_imports.rs (core/pdf/target/debug/deps/no_host_imports-17ccbb1d62120093)
running 1 test
test no_host_imports ... ok
test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s
Running tests/render.rs (core/pdf/target/debug/deps/render-2e1d7e8b19d78595)
running 6 tests
test a_null_zero_length_pair_is_no_frames_not_a_dereference ... ok
test text_with_no_fonts_at_all_still_renders_the_shapes ... ok
test raster_image_is_embedded ... ok
test abi_frames_round_trip ... ok
test renders_text_as_embedded_glyphs ... ok
test two_svgs_make_two_pages ... ok
test result: ok. 6 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.01s
Doc-tests slides_pdf
running 0 tests
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
=== fixtures: node dependencies
v24.19.0
11.17.0
=== fixtures: npm ci (needs the registry — see .amadan/README.md)
added 19 packages, and audited 20 packages in 532ms
5 packages are looking for funding
run `npm fund` for details
found 0 vulnerabilities
npm warn allow-scripts 1 package has install scripts not yet covered by allowScripts:
npm warn allow-scripts esbuild@0.28.2 (postinstall: node install.js)
npm warn allow-scripts
npm warn allow-scripts Run `npm approve-scripts --allow-scripts-pending` to review, or `npm approve-scripts <pkg>` to allow.
=== fixtures: the JS side's own tests
✔ one finished upload is register_asset plus the block that uses it, in one batch (13.830182ms)
✔ a record missing its numbers still makes an op the core accepts (1.166102ms)
✔ unusedAssets is what no slide refers to, and remove_asset drops one (3.547327ms)
✔ the Unused images list reconciles by id and names each Remove button (1.36451ms)
✔ an upload refusal is said in words the person can act on (0.254412ms)
✔ clampBox keeps the box inside the frame and no smaller than the minimum (1.251771ms)
✔ fixBox writes four decimals (0.207354ms)
✔ guides are the thirds plus every other block edge (0.214628ms)
✔ snapMove pulls the nearest edge onto a guide within one per cent, and leaves a far one (0.53933ms)
✔ snapResize moves only the edges the handle drags (0.231009ms)
✔ moveBox and resizeBox by handle (0.218845ms)
✔ nudge: arrows move by half a per cent, Shift by two, Alt resizes (0.188489ms)
✔ rectBox reads a block rectangle against its frame (0.17301ms)
✔ typing into a block is a text change on its slide only (8.696685ms)
✔ a block's props changing is structure on its slide (1.618902ms)
✔ adding, moving or removing a block is structure on its slide (1.96298ms)
✔ the notes are text on their slide (0.953027ms)
✔ a slide added, removed or moved is an order change (1.328002ms)
✔ one transaction touching several things reports each once (0.82524ms)
✔ what the ops write passes, and so does an empty document (10.119162ms)
✔ the shapes y-prosemirror and older documents write pass (1.803654ms)
✔ an unknown formatting attribute is reported with the core's message (2.019604ms)
✔ an element inside a paragraph, a non-paragraph child and bare text are reported (2.906819ms)
✔ the unknownmark poison shape is what the check refuses (1.730028ms)
✔ y-prosemirror 1.3.7 deletes the words under an unknown mark; sanitising first keeps them (4.610829ms)
✔ the vocabulary is the five marks and nothing else (0.201935ms)
✔ a reload reuses the id this tab stored for the deck (0.997059ms)
✔ two tabs, and two decks in one tab, get different ids (2.309742ms)
✔ a stored value that is not an id, or storage that throws, gives a fresh id (0.396496ms)
✔ a duplicated tab gives up the copied id; the original keeps it (5.947096ms)
✔ a reload finds no rival and keeps its id (2.592496ms)
✔ presence switches id: beats carry the new one and the old one is somebody else (2.158772ms)
✔ an empty body is no frames (1.043064ms)
✔ frames come back in order with their exact bytes (0.365077ms)
✔ a length prefix is big-endian (0.198187ms)
✔ a truncated frame throws rather than returning a short update (1.612249ms)
✔ deck controls are set_meta (12.783101ms)
✔ slide controls are set_slide, and background keeps its colour (2.949279ms)
✔ move up and down are move_slide with the right after (1.506012ms)
✔ block props: value kinds, region, a shape label (1.821427ms)
✔ box fields are set_block on the desktop and set_phone in the phone view (3.653744ms)
✔ move block and the layer buttons (2.017691ms)
✔ add block: region after the selection on flow, a default box on canvas, a heading level that fits (6.06763ms)
✔ a block is named by its type and its first words (1.761296ms)
✔ blockChange: a control element to its op (1.26177ms)
✔ the Blocks list reconciles by id and keeps its buttons (0.974086ms)
✔ open resolves to the button that closed it and the trimmed field (1.320559ms)
✔ a second open while the dialog is up joins the first (0.186175ms)
✔ a missing dialog mounts as nothing (0.13513ms)
✔ a tab advances its own cursor only when its POST is the very next row (2.871805ms)
✔ the cursor never moves backwards when a response is overtaken by this tab's own write (0.527367ms)
✔ a later response still carries the cursor forward (0.28576ms)
✔ a burst of notifications collapses into one fetch at a time (0.262216ms)
✔ an event naming a seq the tab already has fetches nothing (0.203778ms)
✔ a stopped subscriber drops a response that arrives late (0.391415ms)
✔ stop closes the stream, and start opens exactly one (0.314062ms)
✔ a hidden tab closes its stream on a shortened deadline, and activity reopens it (1.072568ms)
✔ switching away and back inside the grace never drops the stream, so nothing has to be caught up (0.270863ms)
✔ a visible tab that is only being READ closes when idle and comes back on any activity (0.356652ms)
✔ activity while streaming defers the idle close rather than reopening anything (0.214637ms)
✔ a stream failure is never reported as a save failure, and heals on activity (0.273357ms)
✔ an empty response advances the cursor without applying anything (1.705702ms)
✔ a failed fetch leaves the cursor alone so the next notification retries it (0.653472ms)
✔ a decode failure retries once through the raw log, then gives up (1.56395ms)
✔ updatesURL spells the query string exactly, in particular raw as the literal raw=1 (0.182298ms)
✔ empty_doc_views_as_defaults (5.700149ms)
✔ set_meta (3.78613ms)
✔ slides: add, move, remove, set_slide, set_notes (8.173424ms)
✔ duplicate_slide (4.108849ms)
✔ blocks: add, move, remove, set_block (3.923274ms)
✔ set_phone (1.370221ms)
✔ table cells follow rows and cols (1.342369ms)
✔ canvas blocks: box defaults from the region, z from the index (0.980017ms)
✔ assets: register and remove (0.818447ms)
✔ markdown: every mark, code blocks are plain lines (4.594158ms)
✔ batch_is_atomic (2.87506ms)
✔ a batch applies in one transaction with the given origin (0.894198ms)
✔ columns_children_validated (1.745105ms)
✔ layout_switch_round_trip (1.836305ms)
✔ view_matches_snapshot_fixtures (12.004547ms)
✔ columns children have one parent and no cycles (codex 7) (1.156584ms)
✔ canvas-to-flow keeps a concurrent text edit (codex 4) (2.919473ms)
✔ move_block keeps a concurrent text edit, and later inserts land where after says (codex 4) (2.061402ms)
✔ move_slide keeps a concurrent text edit, and later inserts land where after says (codex 4 at slide level) (1.766315ms)
✔ format: {name} and {n} interpolate; an unknown key is left as text (0.821092ms)
✔ a beat on connect, then one every twenty seconds (2.32448ms)
✔ a move posts once, 200ms after the last of a burst, and re-arms the beat (1.551146ms)
✔ a hidden tab stops beating; coming back posts at once (0.427012ms)
✔ applySet leaves this tab out and answers what changed (0.563345ms)
✔ a set with rubbish in it is read for what it does carry (0.252899ms)
✔ initials, and a client id per tab (4.403605ms)
✔ a resync that fails is retried with backoff until it succeeds, without ever running twice at once (2.073995ms)
✔ the browser's online event retries immediately, not just on the next backoff tick (0.322007ms)
✔ reportDivergence before any failure runs the first attempt without a caller ever calling online (1.476057ms)
✔ a permanent 4xx drops its batch instead of retrying it, and does not poison the next edit (85.377737ms)
✔ a network failure or a 5xx is retried, not dropped (60.926844ms)
✔ a 500 is retried the same way a network failure is, never dropped (60.406119ms)
✔ the core-written structure reads as ProseMirror marks (7.265411ms)
✔ a y-prosemirror round trip preserves bold and the link (5.294417ms)
✔ y-prosemirror writes href as the one-key map and marks as {} (0.858451ms)
✔ a plain-string href, written before the map shape, still reads (1.325047ms)
✔ textFragment writes the same shape as writeText (0.606485ms)
✔ safeHref is the server allowlist, and a disallowed href never draws an anchor (0.428103ms)
✔ parseHash splits the slide and the block, and survives a stray % (1.899773ms)
✔ destroy takes the listeners off, and a second mount leaves one of each (0.712091ms)
✔ formatHash is the inverse (1.3753ms)
✔ textBlocks finds the text-bearing blocks and skips the rest (1.346456ms)
✔ mountTarget is the element whose children are the paragraphs (0.180194ms)
✔ paragraphTag keeps the renderer's own markup per type (0.119962ms)
✔ blockFragment finds a block's text by slide and block id (5.516698ms)
✔ notesFragment finds the slide's notes (0.719554ms)
✔ blockIDs and slideIDs are the orders on the stage and the strip (0.734301ms)
✔ cellFragments are a table's cells, row-major (1.033927ms)
✔ a load that fails leaves the stage on the slide it was showing and says so (1.082958ms)
✔ slideAfter is the slide to show once one is gone (0.152493ms)
✔ the queue words map to savestatus states, failed staying failed (1.195086ms)
✔ a dropped batch outranks the queue, for the rest of the session (0.192406ms)
✔ the editor status: the save line and the load error are two lines (0.2693ms)
✔ mountSaveStatus loads estilo's module and mounts it on the line (0.910268ms)
✔ a save-status module that will not load says so and refuses to mount (0.448532ms)
✔ dropTarget: before puts it ahead of the item, after behind it, null means first (1.051971ms)
✔ a drop that leaves the order as it is is no move (0.199761ms)
✔ dropOp is the move_slide (1.153599ms)
✔ labelFor is the slide's first heading, else the numbered fallback (4.681079ms)
✔ flush re-points every dirty thumbnail and relabels it (1.770152ms)
✔ destroy takes the item-menu listener off; a second mount leaves one (0.241458ms)
✔ plan says what to add, drop and where each item goes (0.617324ms)
✔ sync moves only the items out of place and keeps focus (1.009131ms)
✔ desktop view: box and size are the block; hidden and order are always the phone map (2.022039ms)
✔ phone view: everything goes to set_phone, carrying the rest of the map (0.384874ms)
✔ the ops it makes are ones the document takes (9.793828ms)
✔ phoneMap reads only the four keys, and only well-typed (0.218866ms)
✔ the stored view is read defensively (0.386507ms)
✔ linkAt reads the link under the cursor and nothing elsewhere (1.888431ms)
✔ setLink marks the selection (1.564641ms)
✔ setLink on a collapsed cursor inside a link replaces that link (0.473979ms)
✔ setLink with nothing selected and no link does nothing (0.162661ms)
✔ removeLink clears the link under the cursor (0.304704ms)
✔ the keymap binds every documented shortcut (0.176508ms)
✔ Mod-b toggles bold through the keymap (0.449493ms)
✔ setLink refuses an address outside the allowlist and writes nothing (0.427833ms)
✔ the state machine runs choose → sign → put → register → op (3.141514ms)
✔ a file the deck will not take never reaches the network (0.821583ms)
✔ alt text is required before the bytes move, unless the image is decorative (0.410461ms)
✔ a step that fails stops the ones after it and reports its own code (0.694017ms)
✔ a failure that is not ours still becomes an UploadError (0.347645ms)
✔ a second pick while one is in flight is refused, not raced (0.483557ms)
✔ an unreadable size is zero rather than a failure (3.528453ms)
✔ a per-call applyOp wins, so an upload lands on the block it was chosen for (0.340351ms)
✔ checkFile takes exactly the four types (0.446207ms)
✔ sha256Hex is the hex digest of the bytes (10.349539ms)
✔ refusal reads this app's JSON error shape, and survives one that is not (0.261896ms)
✔ malformed fonts are null (2.817063ms)
✔ a malformed background is the theme default (1.323164ms)
✔ a malformed box is null (0.675973ms)
✔ the phone layer keeps only its typed fields, order as a whole number (1.438146ms)
✔ assets are typed or skipped (0.333478ms)
✔ every poison update is deterministic bytes that apply to any deck (5.882476ms)
ℹ tests 158
ℹ suites 0
ℹ pass 158
ℹ fail 0
ℹ cancelled 0
ℹ skipped 0
ℹ todo 0
ℹ duration_ms 288.372419
=== the vectors must match a fresh generation
canvas: 22 ops, 3715 bytes
columns: 23 ops, 3134 bytes
every-block: 36 ops, 3180 bytes
table: 14 ops, 1509 bytes
title-only: 6 ops, 1136 bytes
=== the editor bundle must match a fresh build
wrote internal/slides/static/editor.0463180baf5aab9f.js (376416 bytes)
=== go: vet, gofmt, test, migration check
go vet ./...
go test ./...
? amadan.net/oficina/slides/cmd/slides [no test files]
ok amadan.net/oficina/slides/internal/slides 12.048s
ok amadan.net/oficina/slides/internal/slides/core 2.462s
ok amadan.net/oficina/slides/internal/slides/deck (cached)
ok amadan.net/oficina/slides/internal/slides/fonts (cached)
? amadan.net/oficina/slides/internal/slides/icons [no test files]
? amadan.net/oficina/slides/internal/slides/keymailtest [no test files]
ok amadan.net/oficina/slides/internal/slides/layout (cached)
ok amadan.net/oficina/slides/internal/slides/live (cached)
ok amadan.net/oficina/slides/internal/slides/pdfcore (cached)
ok amadan.net/oficina/slides/internal/slides/present (cached)
ok amadan.net/oficina/slides/internal/slides/render (cached)
ok amadan.net/oficina/slides/internal/slides/svg (cached)
ok amadan.net/oficina/slides/internal/slidestest 37.592s
? amadan.net/oficina/slides/scripts/writeestilo [no test files]
go run amadan.net/rastrillo/rastrillo/cmd/rastrillo migration check
rastrillo migration check: models and migrations agree
python3 scripts/credits.py --check
credits: checked
gate: ok
diff --git a/AGENTS.md b/AGENTS.md| index ce5858b..58547a9 100644 |
| --- a/AGENTS.md |
| +++ b/AGENTS.md |
| @@ -53,7 +53,7 @@ seeded on first sign-in — and comes back out as a PDF. |
| `form-action` to it); any other gets `303 ?sent=1`, and only a |
| permitted one is mailed, by a worker after the response (`mailQueue`), so not even the response time differs. Admission is |
| rastrillo/auth's `Authorize`, after verification, and its refusal is |
| - the door with `?err=refused` (`doorOnRefusal`), not rastrillo's bare |
| + the door, rendered in the refusal's own 403 (`doorOnRefusal`; never a query anyone could type), not rastrillo's bare |
| text. `?force=1&err=keymail` (a failed Keymail exchange) makes the |
| form ask for a link instead. The list is also **rechecked on |
| every request** that resolves a principal, so taking an address off it |
diff --git a/internal/slides/app.go b/internal/slides/app.go| index af0cc97..f81d272 100644 |
| --- a/internal/slides/app.go |
| +++ b/internal/slides/app.go |
| @@ -80,8 +80,8 @@ func New(d *db.DB, cfg Config) (*http.ServeMux, *app, error) { |
| if a.homeRoutes == nil { |
| r.Get(signinPath, a.signin) |
| r.Post(signinPath, a.newBegin(authPlugin.Begin)) |
| - r.Get("/auth/callback", doorOnRefusal(authPlugin.Callback, signinPath)) |
| - r.Get("/auth/verify", doorOnRefusal(authPlugin.Verify, signinPath)) |
| + r.Get("/auth/callback", doorOnRefusal(authPlugin.Callback, a.signin)) |
| + r.Get("/auth/verify", doorOnRefusal(authPlugin.Verify, a.signin)) |
| r.Get(landedPath, a.landed) |
| r.Post("/signout", signedOutAfter(authPlugin.Signout)) |
| r.Get("/signed-out", a.signedOut) |
| @@ -90,8 +90,8 @@ func New(d *db.DB, cfg Config) (*http.ServeMux, *app, error) { |
| r.Get(signinPath, a.homeSignin) |
| r.Get("/signin/local", a.signin) |
| r.Post(signinPath, h.LocalGuard(a.newBegin(authPlugin.Begin))) |
| - r.Get("/auth/callback", h.LocalGuard(doorOnRefusal(authPlugin.Callback, "/signin/local"))) |
| - r.Get("/auth/verify", h.LocalGuard(doorOnRefusal(authPlugin.Verify, "/signin/local"))) |
| + r.Get("/auth/callback", h.LocalGuard(doorOnRefusal(authPlugin.Callback, a.signin))) |
| + r.Get("/auth/verify", h.LocalGuard(doorOnRefusal(authPlugin.Verify, a.signin))) |
| r.Post("/signout", h.Signout) |
| r.Get("/signed-out", h.SignedOut) |
| r.Get(connect.LocalCompletePath, h.LocalComplete) |
diff --git a/internal/slides/auth.go b/internal/slides/auth.go| index 551f5f8..45772e7 100644 |
| --- a/internal/slides/auth.go |
| +++ b/internal/slides/auth.go |
| @@ -234,14 +234,19 @@ const rauthRefusal = "This address is verified but not admitted here." |
| // doorOnRefusal wraps rauth's Callback and Verify, the two handlers |
| // that end in admit(), and turns its bare-text refusal into the sign-in |
| -// door: a 303 to the local form with ?err=refused, which says this |
| -// address cannot sign in here and offers the form for a different one. |
| -// Every other answer, cookies included, passes through untouched. |
| +// door, rendered right there in the refusal's own response: the form, |
| +// with "That address can't sign in to Slides" above it, and a 403. Every |
| +// other answer, cookies included, passes through untouched. |
| // |
| -// It is told only to somebody who has just verified the address, so it |
| -// is no oracle. Remove it when rastrillo grows a refusal hook (a bump |
| -// past this pin; see the fix/keymail-signin discussion). |
| -func doorOnRefusal(next http.HandlerFunc, form string) http.HandlerFunc { |
| +// Rendered, not redirected to ?err=refused: a query parameter is |
| +// something anybody can type, and then the sentence that means "you |
| +// proved this address and it is not admitted" could be shown to |
| +// anybody about nothing (Astra on #20, round 3). The refusal reaches |
| +// door through the request context (refusedHere), which only this |
| +// wrapper sets. It is told only to somebody who has just verified the |
| +// address, so it is no oracle. Remove it when rastrillo grows a refusal |
| +// hook (feat/auth-refused-hook) and the pin is bumped. |
| +func doorOnRefusal(next, door http.HandlerFunc) http.HandlerFunc { |
| return func(w http.ResponseWriter, r *http.Request) { |
| rec := &bufferedResponse{header: make(http.Header)} |
| next(rec, r) |
| @@ -249,8 +254,8 @@ func doorOnRefusal(next http.HandlerFunc, form string) http.HandlerFunc { |
| for _, c := range rec.header.Values("Set-Cookie") { |
| w.Header().Add("Set-Cookie", c) |
| } |
| - w.Header().Set("Cache-Control", "no-store") |
| - http.Redirect(w, r, form+"?err=refused", http.StatusSeeOther) |
| + door(&forcedStatus{ResponseWriter: w, status: http.StatusForbidden}, |
| + r.WithContext(context.WithValue(r.Context(), refusedKey{}, true))) |
| return |
| } |
| for name, values := range rec.header { |
| @@ -266,6 +271,34 @@ func doorOnRefusal(next http.HandlerFunc, form string) http.HandlerFunc { |
| } |
| } |
| +// refusedKey marks a request doorOnRefusal is answering with the door. |
| +type refusedKey struct{} |
| + |
| +// refusedHere reports whether r is a refusal doorOnRefusal is rendering. |
| +func refusedHere(r *http.Request) bool { |
| + v, _ := r.Context().Value(refusedKey{}).(bool) |
| + return v |
| +} |
| + |
| +// forcedStatus answers with status whatever status the page writes. |
| +type forcedStatus struct { |
| + http.ResponseWriter |
| + status int |
| + wrote bool |
| +} |
| + |
| +func (f *forcedStatus) WriteHeader(int) { |
| + if !f.wrote { |
| + f.wrote = true |
| + f.ResponseWriter.WriteHeader(f.status) |
| + } |
| +} |
| + |
| +func (f *forcedStatus) Write(p []byte) (int, error) { |
| + f.WriteHeader(f.status) |
| + return f.ResponseWriter.Write(p) |
| +} |
| + |
| // bufferedResponse holds a whole answer so doorOnRefusal can decide |
| // what to send after seeing it. Callback and Verify answer with a |
| // redirect or a line of text, never anything large. |
| @@ -631,8 +664,9 @@ type signinView struct { |
| // signin serves GET /signin: the form, and the landing spot for every |
| // outcome rauth redirects back to (?sent=1, ?err=rate|address|expired| |
| -// keymail|removed|refused|1, ?force=1). rate, address, expired, removed |
| -// and refused each get their own sentence; keymail and a bare failure |
| +// keymail|removed|1, ?force=1), and the door doorOnRefusal renders in a |
| +// refusal's own response (refusedHere). rate, address, expired, removed |
| +// and a refusal each get their own sentence; keymail and a bare failure |
| // share the default, because both mean the same operational thing — |
| // sign-in did not complete, ask for a new link — and rauth's Verify |
| // deliberately refuses to be more specific than that. ?force=1 (with |
| @@ -653,7 +687,7 @@ type signinView struct { |
| func (a *app) signin(w http.ResponseWriter, r *http.Request) { |
| q := r.URL.Query() |
| ret, hasReturn := safeReturn(q) |
| - if a.home == nil || r.URL.Path == "/signin/local" { |
| + if (a.home == nil || r.URL.Path == "/signin/local") && !refusedHere(r) { |
| if s, ok := a.sessions.From(r); ok { |
| _, outcome := a.currentUser(w, sessions.WithSession(r, s)) |
| switch outcome { |
| @@ -714,22 +748,22 @@ func (a *app) signin(w http.ResponseWriter, r *http.Request) { |
| if hasReturn { |
| form.Return = ret |
| } |
| - switch q.Get("err") { |
| - case "": |
| + switch err := q.Get("err"); { |
| + case refusedHere(r): |
| + // Keymail or a link verified the address and the allowlist does |
| + // not hold it (doorOnRefusal). The form is the way on. Never |
| + // from the query: ?err=refused is the unknown-error default. |
| + form.Error = rastrillo.T(r, "slides.signin.error.refused") |
| + case err == "": |
| // nothing to report |
| - case "rate": |
| + case err == "rate": |
| form.Error = rastrillo.T(r, "slides.signin.error.rate") |
| - case "address": |
| + case err == "address": |
| // An address error belongs to the field, not a banner. |
| form.AddressError = rastrillo.T(r, "slides.signin.error.address") |
| - case "expired": |
| + case err == "expired": |
| form.Error = rastrillo.T(r, "slides.signin.error.expired") |
| - case "refused": |
| - // Keymail or a link verified the address and the allowlist does |
| - // not hold it (doorOnRefusal). The form below is the way on: a |
| - // different address. |
| - form.Error = rastrillo.T(r, "slides.signin.error.refused") |
| - case "removed": |
| + case err == "removed": |
| // Not "sign-in did not complete": this address had access and |
| // no longer does (offboard). Asking for another link will not |
| // help, and the sentence says so. |
diff --git a/internal/slides/auth_test.go b/internal/slides/auth_test.go| index 3c6cb55..8865cf0 100644 |
| --- a/internal/slides/auth_test.go |
| +++ b/internal/slides/auth_test.go |
| @@ -86,8 +86,10 @@ func countCreates(t *testing.T, g *gorm.DB) func() int { |
| // insert. |
| func TestEnsureUserWritesOnceOnly(t *testing.T) { |
| d := testDB(t) |
| - if _, _, err := newApp(d, Config{Env: EnvDevelopment, Logger: quietLogger()}); err != nil { |
| + if a, _, err := newApp(d, Config{Env: EnvDevelopment, Logger: quietLogger()}); err != nil { |
| t.Fatalf("newApp: %v", err) |
| + } else { |
| + t.Cleanup(func() { a.Close() }) |
| } |
| creates := countCreates(t, d.G) |
| @@ -135,8 +137,10 @@ func TestEnsureUserWritesOnceOnly(t *testing.T) { |
| // disjoint sets of decks depending on which one a request found. |
| func TestEnsureUserNormalizesTheAddress(t *testing.T) { |
| d := testDB(t) |
| - if _, _, err := newApp(d, Config{Env: EnvDevelopment, Logger: quietLogger()}); err != nil { |
| + if a, _, err := newApp(d, Config{Env: EnvDevelopment, Logger: quietLogger()}); err != nil { |
| t.Fatalf("newApp: %v", err) |
| + } else { |
| + t.Cleanup(func() { a.Close() }) |
| } |
| ctx := context.Background() |
| @@ -168,8 +172,10 @@ func TestEnsureUserNormalizesTheAddress(t *testing.T) { |
| // create a row owning decks that nobody could ever sign in as. |
| func TestEnsureUserRefusesAnEmptyAddress(t *testing.T) { |
| d := testDB(t) |
| - if _, _, err := newApp(d, Config{Env: EnvDevelopment, Logger: quietLogger()}); err != nil { |
| + if a, _, err := newApp(d, Config{Env: EnvDevelopment, Logger: quietLogger()}); err != nil { |
| t.Fatalf("newApp: %v", err) |
| + } else { |
| + t.Cleanup(func() { a.Close() }) |
| } |
| if _, _, err := ensureUser(context.Background(), d.G, " "); err == nil { |
| t.Fatal("ensureUser accepted a blank address; want an error") |
diff --git a/internal/slides/config_test.go b/internal/slides/config_test.go| index 17060bc..c8b1568 100644 |
| --- a/internal/slides/config_test.go |
| +++ b/internal/slides/config_test.go |
| @@ -42,6 +42,7 @@ func TestDevelopmentStoresTheResolvedConfig(t *testing.T) { |
| if err != nil { |
| t.Fatalf("newApp: %v", err) |
| } |
| + t.Cleanup(func() { a.Close() }) |
| if a.cfg.Origin != DefaultOrigin { |
| t.Errorf("a.cfg.Origin = %q, want the resolved %q", a.cfg.Origin, DefaultOrigin) |
| } |
diff --git a/internal/slides/keymail_home_test.go b/internal/slides/keymail_home_test.go| index b0a8d0f..667c608 100644 |
| --- a/internal/slides/keymail_home_test.go |
| +++ b/internal/slides/keymail_home_test.go |
| @@ -13,6 +13,7 @@ import ( |
| "regexp" |
| "strings" |
| "testing" |
| + "time" |
| "amadan.net/oficina/home/connect" |
| "amadan.net/oficina/slides/internal/slides/keymailtest" |
| @@ -29,6 +30,18 @@ func TestMain(m *testing.M) { |
| os.Exit(1) |
| } |
| code := m.Run() |
| + // No test may leave a sign-in mail worker running: every app and |
| + // every queue a test builds is closed in its cleanup. |
| + if code == 0 { |
| + deadline := time.Now().Add(5 * time.Second) |
| + for mailWorkers() > 0 && time.Now().Before(deadline) { |
| + time.Sleep(10 * time.Millisecond) |
| + } |
| + if n := mailWorkers(); n > 0 { |
| + fmt.Fprintf(os.Stderr, "FAIL: %d sign-in mail queue goroutines still running after the tests\n", n) |
| + code = 1 |
| + } |
| + } |
| restore() |
| os.Exit(code) |
| } |
| @@ -98,13 +111,12 @@ func TestHomeLocalKeymailIsAContinuationAndRefusesAtTheDoor(t *testing.T) { |
| } |
| cb := do(http.MethodGet, "/auth/callback?"+url.Values{"state": {u.Query().Get("state")}, "code": {km.Approve(stranger)}}.Encode(), nil, rec.Result().Cookies()) |
| - if cb.Code != http.StatusSeeOther || cb.Header().Get("Location") != "/signin/local?err=refused" { |
| - t.Fatalf("Home-mode callback for a non-permitted address: %d %q, want 303 /signin/local?err=refused\n%s", cb.Code, cb.Header().Get("Location"), cb.Body.String()) |
| - } |
| // This mux has no locale middleware, so the catalog key itself is |
| // what proves the refusal sentence was chosen. |
| - door := do(http.MethodGet, "/signin/local?err=refused", nil, nil) |
| - if body := door.Body.String(); door.Code != http.StatusOK || !strings.Contains(body, "slides.signin.error.refused") || !strings.Contains(body, `name="address"`) { |
| - t.Fatalf("refusal door: %d\n%s", door.Code, body) |
| + if body := cb.Body.String(); cb.Code != http.StatusForbidden || !strings.Contains(body, "slides.signin.error.refused") || !strings.Contains(body, `name="address"`) { |
| + t.Fatalf("Home-mode callback for a non-permitted address: %d %q, want 403 and the local door with the refusal\n%s", cb.Code, cb.Header().Get("Location"), body) |
| + } |
| + if spoof := do(http.MethodGet, "/signin/local?err=refused", nil, nil).Body.String(); strings.Contains(spoof, "slides.signin.error.refused") { |
| + t.Fatal("anybody can show the refusal by visiting /signin/local?err=refused") |
| } |
| } |
diff --git a/internal/slides/mailqueue.go b/internal/slides/mailqueue.go| index 27d227c..1a585c8 100644 |
| --- a/internal/slides/mailqueue.go |
| +++ b/internal/slides/mailqueue.go |
| @@ -38,11 +38,19 @@ import ( |
| // surfaced: a failure only a permitted address can reach is the oracle |
| // again. |
| // |
| +// Nothing but the log pump ever writes to the logger. The worker and |
| +// close hand their lines to logf, which never blocks: a buffered |
| +// channel, and a counted drop when it is full. A stalled log sink can |
| +// therefore hold only the pump's one write — never a request, never the |
| +// worker, never close (Astra on #20, round 3). The pump ends when the |
| +// worker does. |
| +// |
| // close drains what is queued within drainTimeout. Past it, the send |
| // in flight is cancelled through its context, everything still queued |
| -// is abandoned with a log line, and close waits a short grace for the |
| +// is abandoned and counted, and close waits a short grace for the |
| // worker to stop. A mailer that ignores its context is the only way a |
| -// worker outlives close, and that is logged too. |
| +// worker outlives close; that is counted in stuck and logged, best |
| +// effort, too. |
| type mailQueue struct { |
| next mail.Sender |
| admits func(to string) bool |
| @@ -63,6 +71,24 @@ type mailQueue struct { |
| ctx context.Context // cancelled when close gives up waiting |
| cancel context.CancelFunc |
| done chan struct{} |
| + |
| + logMu sync.RWMutex // logf reads logsClosed; the worker's exit sets it |
| + logsClosed bool |
| + logs chan logLine // to the pump; logf never blocks on it |
| + unlogged atomic.Int64 // lines handed over and not yet written |
| + lostLogs atomic.Int64 // lines logf could not hand over |
| + stuck atomic.Bool // close gave up on a worker that ignored cancellation |
| + |
| + // refusedLog, when set, is the line the worker logs (through logf, |
| + // with a running count and never the address) for each link it |
| + // refuses. |
| + refusedLog string |
| + refusals atomic.Int64 |
| +} |
| + |
| +type logLine struct { |
| + msg string |
| + args []any |
| } |
| type mailJob struct { |
| @@ -75,9 +101,16 @@ const ( |
| mailSendTimeout = time.Minute |
| mailDrainTimeout = 30 * time.Second |
| mailAbandonGrace = 5 * time.Second |
| + mailLogDepth = 32 |
| ) |
| func newMailQueue(next mail.Sender, admits func(string) bool, gate func(context.Context) bool, logger *slog.Logger) *mailQueue { |
| + return newMailQueueLogging(next, admits, gate, logger, "") |
| +} |
| + |
| +// newMailQueueLogging is newMailQueue with refusedLog set (see the |
| +// field). |
| +func newMailQueueLogging(next mail.Sender, admits func(string) bool, gate func(context.Context) bool, logger *slog.Logger, refusedLog string) *mailQueue { |
| if logger == nil { |
| logger = slog.Default() |
| } |
| @@ -85,7 +118,8 @@ func newMailQueue(next mail.Sender, admits func(string) bool, gate func(context. |
| q := &mailQueue{next: next, admits: admits, gate: gate, logger: logger, |
| drainTimeout: mailDrainTimeout, sendTimeout: mailSendTimeout, |
| jobs: make(chan mailJob, mailQueueDepth), ctx: ctx, cancel: cancel, |
| - done: make(chan struct{})} |
| + done: make(chan struct{}), logs: make(chan logLine, mailLogDepth), refusedLog: refusedLog} |
| + go q.pump() |
| go q.run() |
| return q |
| } |
| @@ -114,8 +148,44 @@ func (q *mailQueue) Send(ctx context.Context, to, subject, body string) error { |
| return nil |
| } |
| +// logf hands one error line to the pump. It never blocks: when the |
| +// pump is behind, the line is counted in lostLogs instead. |
| +func (q *mailQueue) logf(msg string, args ...any) { |
| + q.logMu.RLock() |
| + defer q.logMu.RUnlock() |
| + if q.logsClosed { |
| + q.lostLogs.Add(1) |
| + return |
| + } |
| + q.unlogged.Add(1) |
| + select { |
| + case q.logs <- logLine{msg: msg, args: args}: |
| + default: |
| + q.unlogged.Add(-1) |
| + q.lostLogs.Add(1) |
| + } |
| +} |
| + |
| +// pump is the only goroutine that writes to the logger. It ends when |
| +// the worker closes logs on its way out. |
| +func (q *mailQueue) pump() { |
| + for l := range q.logs { |
| + if n := q.lostLogs.Swap(0); n > 0 { |
| + q.logger.Error("slides: sign-in mail log lines lost to a slow log sink", "count", n) |
| + } |
| + q.logger.Error(l.msg, l.args...) |
| + q.unlogged.Add(-1) |
| + } |
| +} |
| + |
| func (q *mailQueue) run() { |
| defer close(q.done) |
| + defer func() { // after the last logf below; ends the pump |
| + q.logMu.Lock() |
| + q.logsClosed = true |
| + close(q.logs) |
| + q.logMu.Unlock() |
| + }() |
| abandoned := 0 |
| for job := range q.jobs { |
| q.reportDrops() |
| @@ -128,7 +198,7 @@ func (q *mailQueue) run() { |
| } |
| q.reportDrops() |
| if abandoned > 0 { |
| - q.logger.Error("slides: sign-in links abandoned at shutdown", "count", abandoned) |
| + q.logf("slides: sign-in links abandoned at shutdown", "count", abandoned) |
| } |
| } |
| @@ -136,7 +206,7 @@ func (q *mailQueue) run() { |
| // Here, on the worker, so the request path never writes a log line. |
| func (q *mailQueue) reportDrops() { |
| if n := q.dropped.Swap(0); n > 0 { |
| - q.logger.Error("slides: sign-in mail queue full; links dropped", "count", n) |
| + q.logf("slides: sign-in mail queue full; links dropped", "count", n) |
| } |
| } |
| @@ -145,24 +215,33 @@ func (q *mailQueue) reportDrops() { |
| func (q *mailQueue) deliver(job mailJob) { |
| defer func() { |
| if p := recover(); p != nil { |
| - q.logger.Error("slides: sign-in mail worker recovered from a panic", "panic", fmt.Sprint(p)) |
| + q.logf("slides: sign-in mail worker recovered from a panic", "panic", fmt.Sprint(p)) |
| } |
| }() |
| if !job.gated || !q.admits(job.to) { |
| // Not admitted: the link the auth plugin stored is never |
| // delivered, so it is never redeemed. No address in the log. |
| + if q.refusedLog != "" { |
| + q.logf(q.refusedLog, "stage", "signin.gate", "refusals_since_boot", q.refusals.Add(1)) |
| + } |
| return |
| } |
| ctx, cancel := context.WithTimeout(q.ctx, q.sendTimeout) |
| defer cancel() |
| if err := q.next.Send(ctx, job.to, job.subject, job.body); err != nil { |
| - q.logger.Error("slides: send sign-in link", "err", err) |
| + q.logf("slides: send sign-in link", "err", err) |
| } |
| } |
| -// wait blocks until every link queued so far has been sent or refused. |
| -// Tests use it to read the mailer afterwards. |
| -func (q *mailQueue) wait() { q.pending.Wait() } |
| +// wait blocks until every link queued so far has been sent or refused, |
| +// and every line logged about them has been written. Tests use it to |
| +// read the mailer, and the log, afterwards. |
| +func (q *mailQueue) wait() { |
| + q.pending.Wait() |
| + for q.unlogged.Load() > 0 { |
| + time.Sleep(time.Millisecond) |
| + } |
| +} |
| // close stops taking links and drains what is queued, within |
| // drainTimeout; then it cancels, abandons the rest, and stops the |
| @@ -186,6 +265,10 @@ func (q *mailQueue) close() { |
| select { |
| case <-q.done: |
| case <-time.After(mailAbandonGrace): |
| - q.logger.Error("slides: sign-in mail worker ignored cancellation; left running") |
| + // Counted, not written: logging here could hang close on the |
| + // very sink that may be the trouble. The worker is still running, |
| + // so logf is still safe to call, and never blocks. |
| + q.stuck.Store(true) |
| + q.logf("slides: sign-in mail worker ignored cancellation; left running") |
| } |
| } |
diff --git a/internal/slides/mailqueue_test.go b/internal/slides/mailqueue_test.go| index fbe926f..9dcb969 100644 |
| --- a/internal/slides/mailqueue_test.go |
| +++ b/internal/slides/mailqueue_test.go |
| @@ -75,15 +75,21 @@ func TestMailQueueSendNeverBlocksWhenFull(t *testing.T) { |
| <-done |
| t.Fatal("Send blocked with the queue full: the request path waited on the queue or the log") |
| } |
| - // The drops are the worker's to log, once it is free to. |
| + // The drops are the worker's to log, through the pump, once the |
| + // sink is free. |
| free() |
| q.close() |
| - mu.Lock() |
| - defer mu.Unlock() |
| - for _, m := range msgs { |
| - if strings.Contains(m, "links dropped") { |
| - return |
| + deadline := time.Now().Add(2 * time.Second) |
| + for time.Now().Before(deadline) { |
| + mu.Lock() |
| + for _, m := range msgs { |
| + if strings.Contains(m, "links dropped") { |
| + mu.Unlock() |
| + return |
| + } |
| } |
| + mu.Unlock() |
| + time.Sleep(5 * time.Millisecond) |
| } |
| t.Fatalf("no drop was logged with twice the queue's depth sent; the log has %q", msgs) |
| } |
| @@ -197,3 +203,60 @@ func TestAppCloseStopsTheMailWorker(t *testing.T) { |
| t.Fatal("the sign-in mail worker was still running after app.Close") |
| } |
| } |
| + |
| +// mailWorkers counts goroutines running a sign-in mail queue's worker |
| +// or log pump — the targeted leak check (goleak's idea, without the |
| +// dependency) TestMain runs after the package's tests. |
| +func mailWorkers() int { |
| + buf := make([]byte, 1<<22) |
| + stacks := string(buf[:runtime.Stack(buf, true)]) |
| + return strings.Count(stacks, "(*mailQueue).run(") + strings.Count(stacks, "(*mailQueue).pump(") |
| +} |
| + |
| +// TestMailQueueCloseIsBoundedWithAStalledLogger: close reports through |
| +// nothing that can block. With the log sink stalled — every write hangs |
| +// — and a relay that never answers but honours cancellation, close |
| +// still returns within its bound and the worker has exited. Once the |
| +// sink is released, the goroutine count is back to its baseline: the |
| +// only thing a stalled sink can hold is the log pump's one write, never |
| +// close or the worker (Astra, round 3, P2). |
| +func TestMailQueueCloseIsBoundedWithAStalledLogger(t *testing.T) { |
| + baseline := runtime.NumGoroutine() |
| + release := make(chan struct{}) |
| + var once sync.Once |
| + free := func() { once.Do(func() { close(release) }) } |
| + t.Cleanup(free) |
| + var mu sync.Mutex |
| + var msgs []string |
| + honours := funcSender(func(ctx context.Context, _ string) error { |
| + <-ctx.Done() |
| + return ctx.Err() |
| + }) |
| + q := newMailQueue(honours, everyone, nil, slog.New(stuckHandler{release, &mu, &msgs})) |
| + q.drainTimeout = 50 * time.Millisecond |
| + for i := 0; i < 2*mailQueueDepth; i++ { // drops too, so there is plenty to log |
| + _ = q.Send(context.Background(), fmt.Sprintf("p%d@example.test", i), "s", "b") |
| + } |
| + closed := make(chan struct{}) |
| + go func() { q.close(); close(closed) }() |
| + select { |
| + case <-closed: |
| + case <-time.After(2 * time.Second): |
| + free() |
| + <-closed |
| + t.Fatal("close hung on a stalled log sink") |
| + } |
| + select { |
| + case <-q.done: |
| + default: |
| + t.Fatal("the worker was still running after close, held by the stalled log sink") |
| + } |
| + free() |
| + deadline := time.Now().Add(2 * time.Second) |
| + for runtime.NumGoroutine() > baseline && time.Now().Before(deadline) { |
| + time.Sleep(5 * time.Millisecond) |
| + } |
| + if n := runtime.NumGoroutine(); n > baseline { |
| + t.Fatalf("%d goroutines after close and release, %d before", n, baseline) |
| + } |
| +} |
diff --git a/internal/slidestest/keymail_signin_test.go b/internal/slidestest/keymail_signin_test.go| index 33fdc58..c3e2d6d 100644 |
| --- a/internal/slidestest/keymail_signin_test.go |
| +++ b/internal/slidestest/keymail_signin_test.go |
| @@ -3,12 +3,15 @@ package slidestest |
| import ( |
| "fmt" |
| "html" |
| + "io" |
| "net/http" |
| "net/url" |
| "os" |
| "regexp" |
| + "runtime" |
| "strings" |
| "testing" |
| + "time" |
| "amadan.net/oficina/slides/internal/slides/keymailtest" |
| ) |
| @@ -24,6 +27,18 @@ func TestMain(m *testing.M) { |
| os.Exit(1) |
| } |
| code := m.Run() |
| + // No test may leave a sign-in mail worker running: every app and |
| + // every queue a test builds is closed in its cleanup. |
| + if code == 0 { |
| + deadline := time.Now().Add(5 * time.Second) |
| + for mailWorkers() > 0 && time.Now().Before(deadline) { |
| + time.Sleep(10 * time.Millisecond) |
| + } |
| + if n := mailWorkers(); n > 0 { |
| + fmt.Fprintf(os.Stderr, "FAIL: %d sign-in mail queue goroutines still running after the tests\n", n) |
| + code = 1 |
| + } |
| + } |
| restore() |
| os.Exit(code) |
| } |
| @@ -193,26 +208,39 @@ func TestKeymailMemberIsSignedIn(t *testing.T) { |
| // TestKeymailRefusalIsTheDoor: a non-permitted address that Keymail |
| // has verified is refused AFTER verification, and the refusal is the |
| -// sign-in door with an error and a form for a different address — not |
| -// rastrillo's bare-text 403. No session is minted. |
| +// sign-in door, rendered right there with the error and a form for a |
| +// different address — not rastrillo's bare-text 403. No session is |
| +// minted. And the sentence cannot be summoned by anybody else: visiting |
| +// /signin?err=refused shows no such thing (Astra, round 3), because the |
| +// refusal is never a query parameter. |
| func TestKeymailRefusalIsTheDoor(t *testing.T) { |
| app, km := newKeymailApp(t) |
| res, cookies := keymailRoundTrip(t, app, km, keymailStranger) |
| - if res.StatusCode != http.StatusSeeOther { |
| - t.Fatalf("callback for a non-permitted address: %d, want 303 to the door (bare text is the bug)", res.StatusCode) |
| - } |
| - loc := res.Header.Get("Location") |
| - if loc != "/signin?err=refused" { |
| - t.Fatalf("callback for a non-permitted address: Location %q, want /signin?err=refused", loc) |
| + body, _ := io.ReadAll(res.Body) |
| + if res.StatusCode != http.StatusForbidden || res.Header.Get("Location") != "" { |
| + t.Fatalf("callback for a non-permitted address: %d %q, want 403 and the door itself", res.StatusCode, res.Header.Get("Location")) |
| } |
| - door := get(t, app, loc, cookies...) |
| - body := door.Body.String() |
| for _, want := range []string{"estilo-door", `name="address"`, "can’t sign in to Slides"} { |
| - if !strings.Contains(body, want) { |
| + if !strings.Contains(string(body), want) { |
| t.Errorf("refusal page lacks %q:\n%s", want, body) |
| } |
| } |
| + if strings.Contains(string(body), "not admitted here") { |
| + t.Error("the refusal is rastrillo's bare text") |
| + } |
| if rec := get(t, app, "/", cookies...); rec.Code == http.StatusOK { |
| t.Fatal("a refused Keymail sign-in left a working session") |
| } |
| + if spoof := get(t, app, "/signin?err=refused").Body.String(); strings.Contains(spoof, "can’t sign in to Slides") { |
| + t.Fatal("anybody can show the refusal by visiting /signin?err=refused") |
| + } |
| +} |
| + |
| +// mailWorkers counts goroutines running a sign-in mail queue's worker |
| +// or log pump (internal/slides/mailqueue.go) — the targeted leak check |
| +// TestMain runs after the package's tests. |
| +func mailWorkers() int { |
| + buf := make([]byte, 1<<22) |
| + stacks := string(buf[:runtime.Stack(buf, true)]) |
| + return strings.Count(stacks, "(*mailQueue).run(") + strings.Count(stacks, "(*mailQueue).pump(") |
| } |