HOTFIX: Money import of a 15 MB Actual ZIP hangs on Receiving import file #1121

Open
opened 2026-10-05 07:56:20 +00:00 by kayg · 5 comments
Owner

Owner report (2026-10-05, production)

Importing a 15 MB Actual Budget ZIP (Money → Import a budget) sits forever on "Checking export…" / "Receiving import file". Retried after the 09:50 restart: same. The production log shows no Money import activity, so the bytes never seem to reach the multipart loop in crates/plugins/money/src/routes.rs (the progress report "Receiving import file" stays at 0 bytes as far as the UI shows). The route has DefaultBodyLimit 128 MiB.

Leads: (1) the client never starts the body (fetch with a ReadableStream body / duplex half, or the progress subscription blocking the POST); (2) the edge reverse proxy in front of production buffers or limits request bodies (check its config on staging dev.calternal.com, which has the same Quadlet/edge layout); (3) the receive loop tokio::select! drops form.next_field() / field.chunk() every 250 ms; if those futures are not cancel-safe, slow uploads can stall; (4) the UI shows only the stage name, not the byte count.

Wanted: a 15 MB import over a real network path completes; the UI shows bytes received and a percentage; a stalled upload is reported within seconds with Retry.

## Owner report (2026-10-05, production) Importing a 15 MB Actual Budget ZIP (Money → Import a budget) sits forever on "Checking export…" / "Receiving import file". Retried after the 09:50 restart: same. The production log shows no Money import activity, so the bytes never seem to reach the multipart loop in crates/plugins/money/src/routes.rs (the progress report "Receiving import file" stays at 0 bytes as far as the UI shows). The route has DefaultBodyLimit 128 MiB. Leads: (1) the client never starts the body (fetch with a ReadableStream body / duplex half, or the progress subscription blocking the POST); (2) the edge reverse proxy in front of production buffers or limits request bodies (check its config on staging dev.calternal.com, which has the same Quadlet/edge layout); (3) the receive loop `tokio::select!` drops `form.next_field()` / `field.chunk()` every 250 ms; if those futures are not cancel-safe, slow uploads can stall; (4) the UI shows only the stage name, not the byte count. Wanted: a 15 MB import over a real network path completes; the UI shows bytes received and a percentage; a stalled upload is reported within seconds with Retry.
Author
Owner

Started on job/importhang-1121 at production base 4a8e22609e. Tracing multipart receive, browser transport and edge configuration; will test a slow 15 MB upload and commit the repair without pushing or deploying.

Started on job/importhang-1121 at production base 4a8e22609e51f53b037d1296dc757e8f0e2b833a. Tracing multipart receive, browser transport and edge configuration; will test a slow 15 MB upload and commit the repair without pushing or deploying.
Author
Owner

Edge checked (homelab-private k8s/hatsuna/calternal/ingress.yaml and traefik/values.yaml): there is no buffering middleware, so Traefik applies no request-body size limit. Its middlewares are headers, rateLimit 100/s burst 400, and redirect. The ServersTransport has responseHeaderTimeout 3600 s, and the websecure read/write/idle timeouts are 3600 s. Traefik is not the cause; focus on the client and the server receive loop.

Edge checked (homelab-private k8s/hatsuna/calternal/ingress.yaml and traefik/values.yaml): there is no buffering middleware, so Traefik applies no request-body size limit. Its middlewares are headers, rateLimit 100/s burst 400, and redirect. The ServersTransport has responseHeaderTimeout 3600 s, and the websecure read/write/idle timeouts are 3600 s. Traefik is not the cause; focus on the client and the server receive loop.
Author
Owner

Finding: browser upload is ordinary FormData, and its POST does not await a progress subscription. Reviewed the pinned multer 3.1.0 source: next_field delegates to poll_next_field and chunk delegates to the Field stream; parser/buffer state persists across Pending polls. The 250 ms select cancellation is not established as the production root cause.

A comparable local baseline server completed a realistic synthetic Actual ZIP (15,355,251 bytes, 25,000 transactions with synthetic memos) through the real UI: Chromium direct 45,508 ms, paced 1 MiB/s plus latency 59,111 ms; WebKit direct 33,305 ms, paced 69,071 ms. Server receive counts advanced over the paced path. Exact production-base binary verification follows; these samples are not evidence that the owner's production case is fixed.

Confirmed UX defects: a null progress total hides completed bytes; receive stalls have no short UI deadline or Retry; Cancel awaits an unbounded cleanup request. Repair now shows receive bytes/percentage, bounds progress reads, stops idle receive after ten seconds in the browser and fifteen seconds on the server, and makes Cancel immediate. Multipart reads remain pinned across cancellation checks. Focused component tests pass (3 tests).

Edge source inspection: staging dev.calternal.com and production share Traefik rate-limit/headers middleware and calternal-transport. No buffering middleware or body byte cap is configured; entrypoint read/write/idle and upstream response-header timeouts are 3600 seconds. deploy/cloud Quadlet adds no HTTP body policy. Live edge confirmation is still pending.

Known gate finding: bun run check fails on the pre-existing perf-lint app-sidebar.svelte exception fingerprint (render.bound, app-sidebar.svelte#each:10a1aaf3137a2426:1). git fetch origin and git merge origin/dev returned Already up to date.

Finding: browser upload is ordinary FormData, and its POST does not await a progress subscription. Reviewed the pinned multer 3.1.0 source: next_field delegates to poll_next_field and chunk delegates to the Field stream; parser/buffer state persists across Pending polls. The 250 ms select cancellation is not established as the production root cause. A comparable local baseline server completed a realistic synthetic Actual ZIP (15,355,251 bytes, 25,000 transactions with synthetic memos) through the real UI: Chromium direct 45,508 ms, paced 1 MiB/s plus latency 59,111 ms; WebKit direct 33,305 ms, paced 69,071 ms. Server receive counts advanced over the paced path. Exact production-base binary verification follows; these samples are not evidence that the owner's production case is fixed. Confirmed UX defects: a null progress total hides completed bytes; receive stalls have no short UI deadline or Retry; Cancel awaits an unbounded cleanup request. Repair now shows receive bytes/percentage, bounds progress reads, stops idle receive after ten seconds in the browser and fifteen seconds on the server, and makes Cancel immediate. Multipart reads remain pinned across cancellation checks. Focused component tests pass (3 tests). Edge source inspection: staging dev.calternal.com and production share Traefik rate-limit/headers middleware and calternal-transport. No buffering middleware or body byte cap is configured; entrypoint read/write/idle and upstream response-header timeouts are 3600 seconds. deploy/cloud Quadlet adds no HTTP body policy. Live edge confirmation is still pending. Known gate finding: bun run check fails on the pre-existing perf-lint app-sidebar.svelte exception fingerprint (render.bound, app-sidebar.svelte#each:10a1aaf3137a2426:1). git fetch origin and git merge origin/dev returned Already up to date.
Author
Owner

Committed backend repair: 1b7e13479. The focused slow 15 MB receive and stalled/cancelled receive tests pass. Money crate gate output:

    Finished `dev` profile [unoptimized + debuginfo] target(s) in 3m 41s
    Finished `test` profile [unoptimized + debuginfo] target(s) in 1m 37s
test result: ok. 81 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 48.61s
test result: ok. 27 passed; 0 failed; 3 ignored; 0 measured; 0 filtered out; finished in 16.79s

Live edge checked read-only on the k3s node. dev.calternal.com uses only calternal-ratelimit and calternal-headers, neither has buffering configured. calternal-transport responseHeaderTimeout is 3600s, dialTimeout 10s, idleConnTimeout 90s. The actual Traefik deployment has websecure read/write/idle timeouts of 3600s. On the staging VM the active unit is named calternal-cloud.service; its Quadlet publishes 8080 directly and has no body policy.

The production route previously emitted no Money receive log events, so the owner's absence of log activity alone cannot establish that no body reached the route. Added content-free receive-start and receive-complete events with a byte count, to identify this boundary without exposing export names or rows.

No root-cause claim yet: the exact production-base binary completed the direct Chromium case. Remaining exact-base browser cases and the fixed-build stall/Retry test are running. No deployment, merge into dev, or push was performed.

Committed backend repair: 1b7e13479. The focused slow 15 MB receive and stalled/cancelled receive tests pass. Money crate gate output: ``` Finished `dev` profile [unoptimized + debuginfo] target(s) in 3m 41s Finished `test` profile [unoptimized + debuginfo] target(s) in 1m 37s test result: ok. 81 passed; 0 failed; 1 ignored; 0 measured; 0 filtered out; finished in 48.61s test result: ok. 27 passed; 0 failed; 3 ignored; 0 measured; 0 filtered out; finished in 16.79s ``` Live edge checked read-only on the k3s node. dev.calternal.com uses only calternal-ratelimit and calternal-headers, neither has buffering configured. calternal-transport responseHeaderTimeout is 3600s, dialTimeout 10s, idleConnTimeout 90s. The actual Traefik deployment has websecure read/write/idle timeouts of 3600s. On the staging VM the active unit is named calternal-cloud.service; its Quadlet publishes 8080 directly and has no body policy. The production route previously emitted no Money receive log events, so the owner's absence of log activity alone cannot establish that no body reached the route. Added content-free receive-start and receive-complete events with a byte count, to identify this boundary without exposing export names or rows. No root-cause claim yet: the exact production-base binary completed the direct Chromium case. Remaining exact-base browser cases and the fixed-build stall/Retry test are running. No deployment, merge into dev, or push was performed.
Author
Owner

Added one small public test-helper option: startHttpsFront({ http2: true }). The shared default remains HTTP/1. The option matches the staging edge's HTTP/2-to-HTTP/1 boundary, strips hop-specific headers, records only the protocol version, and closes owned HTTP/2 sessions during cleanup. Focused helper tests cover both protocols and pass (2 tests). The Money transport regression now requires an HTTP/2 browser upload and uses this option. No production protocol configuration changed.

The exact production-base HTTP/1 round completed all five paths: Chromium direct 69,934 ms, paced 49,696 ms; WebKit direct 49,248 ms, paced 71,644 ms; curl --limit-rate 1M 56,615 ms. All previews returned 200 and the expected 25,000 transactions. These are local acceptance timings on a busy shared host, not performance budget measurements.

Server clippy gate also passed:

    Finished `dev` profile [unoptimized + debuginfo] target(s) in 15m 34s
Added one small public test-helper option: startHttpsFront({ http2: true }). The shared default remains HTTP/1. The option matches the staging edge's HTTP/2-to-HTTP/1 boundary, strips hop-specific headers, records only the protocol version, and closes owned HTTP/2 sessions during cleanup. Focused helper tests cover both protocols and pass (2 tests). The Money transport regression now requires an HTTP/2 browser upload and uses this option. No production protocol configuration changed. The exact production-base HTTP/1 round completed all five paths: Chromium direct 69,934 ms, paced 49,696 ms; WebKit direct 49,248 ms, paced 71,644 ms; curl --limit-rate 1M 56,615 ms. All previews returned 200 and the expected 25,000 transactions. These are local acceptance timings on a busy shared host, not performance budget measurements. Server clippy gate also passed: ``` Finished `dev` profile [unoptimized + debuginfo] target(s) in 15m 34s ```
Sign in to join this conversation.
No labels
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
kayg/calternal#1121
No description provided.