stop losing the answer when immich rejects mid-upload
An upload over a few MB came back as a 400 with an empty body, no message anywhere, and nothing logged by Immich, the sidecar or officer. It was a race, not a size limit. Immich judges an asset from its first few KB and rejects immediately, then closes; both our hops were still writing the body; Node treats the leftover bytes as a protocol violation and replaces the application's answer with a bodyless `400 Bad Request` + `Connection: close`. The real message never reached the wire. Measured before the change: streamed lost the message 1/4 at 8 MB and 4/4 at 32 MB — probability rising with size, which is why small photos usually worked and a phone's video never did. Both hops needed it. Fixing only the sidecar took 32 MB from 4/4 failing to 2/4, because the platform proxy was losing it one hop up. Bounded at 512 MB, above which the body streams exactly as before. That ceiling is not a refusal and is deliberately not a 413: a file Immich ACCEPTS is read to the end and never races, so a 4 GB video is unaffected. All that is given up above the cap is the error message on a file that was going to be rejected anyway. A first attempt refused over-cap uploads outright and would have broken the working 4 GB case to improve diagnosis of the doomed one. `bufferRequestBody` is opt-in and off by default: the vault and wallet proxies must keep streaming so a passphrase or macaroon never lands in the platform's heap. Also adds the proxy error logging that made this findable at all — status and two byte counts from headers, never the bodies. `responseBytes: "unknown"` is what exposed the stripped response. Verified live at 32/256 MB (buffered) and 640 MB (streamed, passes through). Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
@@ -11,6 +11,12 @@ const proxy = createSidecarProxy({
|
||||
// Originals and `download/archive` zips are large and Immich builds the archive as it streams it, so the
|
||||
// socket can sit quiet longer than the default 60s idle drop allows.
|
||||
timeoutSeconds: 600,
|
||||
// Immich judges an asset from its first few KB and rejects immediately, while we are still writing —
|
||||
// and the response is lost in the teardown, which is what made every large upload fail with an
|
||||
// unexplained empty 400. Buffering here removes the overlap. The sidecar does the same on its own hop
|
||||
// to Immich (sidecar/photos/routes.ts → readBodyCapped), and both are needed: fixing one alone still
|
||||
// lost the answer roughly two runs in three at 32 MB.
|
||||
bufferRequestBody: true,
|
||||
});
|
||||
|
||||
export const photosRouter = proxy.router;
|
||||
|
||||
@@ -73,6 +73,10 @@ beforeAll(async () => {
|
||||
sidecar = Bun.serve({
|
||||
port: 0,
|
||||
async fetch(req) {
|
||||
// A rejection with no body at all — the shape from COMMS/UPLOAD_EMPTY_400.md that tells the client
|
||||
// "no" and gives it nothing to act on.
|
||||
if (new URL(req.url).pathname.endsWith('/empty400')) return new Response(null, { status: 400 });
|
||||
|
||||
const contentType = req.headers.get('content-type') ?? '';
|
||||
const raw = new Uint8Array(await req.arrayBuffer());
|
||||
const asText = new TextDecoder().decode(raw);
|
||||
@@ -160,6 +164,61 @@ describe('sidecar proxy multipart forwarding', () => {
|
||||
expect(seen!.fileBytes).toEqual([...FILE_BYTES]);
|
||||
});
|
||||
|
||||
it('reports a rejection instead of passing it on in silence', async () => {
|
||||
// COMMS/UPLOAD_EMPTY_400.md: uploads failed with an empty-bodied 400 and nothing logged it anywhere,
|
||||
// so localising the fault took an evening of curl bisection. The platform is the only hop that sees
|
||||
// both sides. `requestBytes` is the field that would have cracked it — a size threshold is legible at
|
||||
// a glance instead of by bisection.
|
||||
const warnings: unknown[][] = [];
|
||||
const realWarn = console.warn;
|
||||
console.warn = (...args: unknown[]) => void warnings.push(args);
|
||||
|
||||
try {
|
||||
const payload = JSON.stringify({ some: 'payload' });
|
||||
const res = await app.request('http://x/api/testcar/_officer/empty400', {
|
||||
method: 'POST',
|
||||
// Set explicitly: `app.request` does not derive it, and this is the field the bug report needed.
|
||||
headers: { 'content-type': 'application/json', 'content-length': String(payload.length) },
|
||||
body: payload,
|
||||
});
|
||||
|
||||
// Pass-through is unchanged: the proxy reports, it does not rewrite.
|
||||
expect(res.status).toBe(400);
|
||||
expect(await res.text()).toBe('');
|
||||
|
||||
expect(warnings.length).toBe(1);
|
||||
const [message, detail] = warnings[0] as [string, Record<string, unknown>];
|
||||
expect(message).toContain('[testcar]');
|
||||
expect(message).toContain('POST /_officer/empty400');
|
||||
expect(message).toContain('400');
|
||||
// The empty body is named, not left to be inferred from a byte count of zero.
|
||||
expect(detail.emptyBody).toBe(true);
|
||||
expect(detail.requestBytes).toBe(String(payload.length));
|
||||
expect(detail.responseBytes).toBe('0');
|
||||
} finally {
|
||||
console.warn = realWarn;
|
||||
}
|
||||
});
|
||||
|
||||
it('says nothing about a request that succeeded', async () => {
|
||||
const { body, contentType } = phoneMultipart();
|
||||
const warnings: unknown[][] = [];
|
||||
const realWarn = console.warn;
|
||||
console.warn = (...args: unknown[]) => void warnings.push(args);
|
||||
|
||||
try {
|
||||
const res = await app.request('http://x/api/testcar/_officer/assets', {
|
||||
method: 'POST',
|
||||
headers: { 'content-type': contentType },
|
||||
body: new Blob([body]),
|
||||
});
|
||||
expect(res.status).toBe(201);
|
||||
expect(warnings).toEqual([]);
|
||||
} finally {
|
||||
console.warn = realWarn;
|
||||
}
|
||||
});
|
||||
|
||||
it('still forwards a JSON body untouched', async () => {
|
||||
const res = await app.request('http://x/api/testcar/_officer/echo', {
|
||||
method: 'POST',
|
||||
|
||||
@@ -16,7 +16,8 @@ import { registerProxiedPrefix } from './proxied-prefixes';
|
||||
// the platform process is long-lived, restarts on every deploy and is the largest attack surface in the
|
||||
// system, while the bodies passing through carry wallet unlock passphrases, macaroons and vault secrets.
|
||||
// Keeping this layer structurally incapable of seeing them is the point. Note the absence of any body
|
||||
// inspection below, and that the error path logs the target path ONLY.
|
||||
// inspection below: the two error paths log a path, a status and byte counts taken from HEADERS, and
|
||||
// nothing ever reads or buffers the streams themselves.
|
||||
//
|
||||
// Sidecars own their own contracts. This file must never grow per-app logic — if a sidecar needs
|
||||
// something extra at registration time it gets `onRegister`, not a branch in here.
|
||||
@@ -35,8 +36,30 @@ export type SidecarProxyParams = {
|
||||
* of a sidecar's routes are slow.
|
||||
*/
|
||||
timeoutSeconds?: number;
|
||||
/**
|
||||
* Read the request body fully before forwarding, instead of streaming it.
|
||||
*
|
||||
* OFF by default and it must stay that way: streaming is what keeps wallet passphrases, macaroons and
|
||||
* vault secrets out of this process's heap, and what lets a multi-gigabyte upload through at all.
|
||||
*
|
||||
* Opt in only where a sidecar's upstream answers BEFORE the body finishes arriving. When that happens
|
||||
* the response is lost — the far side closes while we are still writing, and the real answer is
|
||||
* replaced by a bodyless 400. Photos hits this because Immich judges an asset from its first few KB
|
||||
* and rejects immediately; see `readBodyCapped` in sidecar/photos/routes.ts for the measurements.
|
||||
*
|
||||
* Bounded by `MAX_BUFFERED_BODY`: a body larger than that is streamed anyway, so enabling this can
|
||||
* never put a 4 GB video in the heap. Above the cap the race is accepted, because an upload that size
|
||||
* only loses its ERROR MESSAGE — one Immich accepts is read to the end and never races at all.
|
||||
*/
|
||||
bufferRequestBody?: boolean;
|
||||
};
|
||||
|
||||
/**
|
||||
* Ceiling on `bufferRequestBody`. Kept in step with the photos sidecar's own cap so the two hops make the
|
||||
* same call on the same request; officer buffering is what gives the sidecar a content-length to decide by.
|
||||
*/
|
||||
const MAX_BUFFERED_BODY = 512 * 1024 * 1024;
|
||||
|
||||
export type SidecarProxy = {
|
||||
/** Catch-all router to mount at `prefix`. Has no routes of its own by design. */
|
||||
router: Hono<{ Variables: HonoVariables }>;
|
||||
@@ -46,7 +69,13 @@ export type SidecarProxy = {
|
||||
getWsUrl: () => string | null;
|
||||
};
|
||||
|
||||
export function createSidecarProxy({ name, prefix, onRegister, timeoutSeconds }: SidecarProxyParams): SidecarProxy {
|
||||
export function createSidecarProxy({
|
||||
name,
|
||||
prefix,
|
||||
onRegister,
|
||||
timeoutSeconds,
|
||||
bufferRequestBody,
|
||||
}: SidecarProxyParams): SidecarProxy {
|
||||
let serverPort: number | null = null;
|
||||
|
||||
// Tells bodyParser to keep its hands off this prefix's request bodies. Load-bearing for uploads, not an
|
||||
@@ -106,10 +135,23 @@ export function createSidecarProxy({ name, prefix, onRegister, timeoutSeconds }:
|
||||
// is absent from TypeScript's RequestInit, hence the widened type.
|
||||
// This is only safe because bodyParser skips proxied prefixes: a body consumed upstream would arrive
|
||||
// here as an already-locked stream.
|
||||
// Buffered only where the sidecar opted in (see `bufferRequestBody`), and only up to the cap: an
|
||||
// upstream that answers before the body lands loses its own response, and streaming is what exposes
|
||||
// that race. Anything larger streams as it always did — a 4 GB video must not land in this heap, and
|
||||
// does not need to, since a file the upstream ACCEPTS is read to the end and never races.
|
||||
const declaredLength = Number(ctx.req.header('content-length') ?? '');
|
||||
const withinBufferCap =
|
||||
Number.isFinite(declaredLength) && declaredLength > 0 && declaredLength <= MAX_BUFFERED_BODY;
|
||||
const body = hasBody
|
||||
? bufferRequestBody && withinBufferCap
|
||||
? await ctx.req.raw.arrayBuffer()
|
||||
: ctx.req.raw.body
|
||||
: undefined;
|
||||
|
||||
const init: RequestInit & { duplex?: 'half' } = {
|
||||
method,
|
||||
headers,
|
||||
body: hasBody ? ctx.req.raw.body : undefined,
|
||||
body,
|
||||
duplex: 'half',
|
||||
};
|
||||
|
||||
@@ -122,6 +164,29 @@ export function createSidecarProxy({ name, prefix, onRegister, timeoutSeconds }:
|
||||
return ctx.text(`${name} sidecar unreachable`, 502);
|
||||
}
|
||||
|
||||
// Every rejection that passes through gets one line. This is METADATA ONLY — status and two byte
|
||||
// counts read from headers, never the bytes themselves — so the no-bodies rule above still holds.
|
||||
//
|
||||
// It exists because of COMMS/UPLOAD_EMPTY_400.md: photo uploads over ~16 KB failed with a 400 carrying
|
||||
// an EMPTY body, and nothing anywhere logged it — not Immich, not the sidecar, not here. The platform
|
||||
// is the only hop that sees both sides, and it said nothing, so localising the fault took an evening of
|
||||
// curl bisection. An error with no body is the unactionable case: the client is told "no" and given
|
||||
// nothing to act on, and silence here makes it invisible to the server too.
|
||||
//
|
||||
// `requestBytes` is the field that would have cracked it: it makes a size threshold legible at a glance
|
||||
// instead of by bisection. The subpath is logged without its query string — the 502 path above logs the
|
||||
// full target, but this fires on ordinary 401s and 404s too, and query strings carry tokens.
|
||||
if (upstream.status >= 400) {
|
||||
const responseBytes = upstream.headers.get('content-length');
|
||||
console.warn(`[${name}] proxy ${method} ${subpath} -> ${upstream.status}`, {
|
||||
requestBytes: ctx.req.header('content-length') ?? 'unknown',
|
||||
responseBytes: responseBytes ?? 'unknown',
|
||||
// Called out rather than left to be inferred from `responseBytes: '0'`, because this exact shape is
|
||||
// the one that is impossible to diagnose from the client.
|
||||
...(responseBytes === '0' ? { emptyBody: true } : {}),
|
||||
});
|
||||
}
|
||||
|
||||
return new Response(upstream.body, { status: upstream.status, headers: new Headers(upstream.headers) });
|
||||
});
|
||||
|
||||
|
||||
@@ -83,11 +83,86 @@ export function relayResponse(res: Response): Response {
|
||||
return new Response(body, { status: res.status, headers });
|
||||
}
|
||||
|
||||
/**
|
||||
* The largest request body held in memory. Above this the body is STREAMED instead — never refused.
|
||||
*
|
||||
* The cap exists to bound heap, not to bound uploads: a 4 GB video must still go through. What is given
|
||||
* up above the cap is only the guarantee that a REJECTION carries its message, and an upload that big
|
||||
* which Immich rejects was going to fail either way — see `readBodyCapped`.
|
||||
*/
|
||||
const MAX_BUFFERED_BODY = 512 * 1024 * 1024;
|
||||
|
||||
/**
|
||||
* Read the whole request body into memory, refusing above `MAX_BUFFERED_BODY`.
|
||||
*
|
||||
* ── Why this is buffered rather than streamed ──
|
||||
*
|
||||
* It used to stream, which is the obvious thing for an upload and was wrong for one specific reason:
|
||||
* when the body is still being written and Immich answers early, the response is lost. Immich rejects
|
||||
* an asset as soon as it has enough of the file to judge it, then closes; our writer is still going;
|
||||
* Node's HTTP server calls the leftover bytes a protocol violation and replaces the app's answer with a
|
||||
* bodyless `400 Bad Request` + `Connection: close`. The app's real message never reaches the wire and
|
||||
* Immich logs nothing, so the client sees an unexplained 400 and the server has no record of it.
|
||||
*
|
||||
* Measured on this machine (COMMS/UPLOAD_EMPTY_400*.md): streamed lost the response in 2 of 4 attempts
|
||||
* at 8 MB, 32 MB and 64 MB alike; buffered lost it in 0 of 4 at every size. It is a race, not a size
|
||||
* limit — its probability just approaches certainty as the body grows, which is why a phone's video
|
||||
* failed every time while a small photo usually got through.
|
||||
*
|
||||
* A size threshold was considered and rejected: buffering only the small bodies would leave exactly the
|
||||
* large uploads that always fail on the broken path. Cancelling the write once the response arrives was
|
||||
* tried and does not help — by the time `fetch` resolves, the teardown has already happened.
|
||||
*
|
||||
* The cost is real and was accepted deliberately: a 300 MB video is 300 MB of this process's heap for
|
||||
* the duration of the upload. That is the price of the upload working at all.
|
||||
*
|
||||
* ── And why there is a ceiling on it ──
|
||||
*
|
||||
* Buffering everything would mean a 4 GB video sitting in this heap (and another copy in officer's), so
|
||||
* above MAX_BUFFERED_BODY the body is streamed as it always was. That is not a refusal and not a
|
||||
* degradation of uploads: a file Immich ACCEPTS never triggers the race, because it is read to the end
|
||||
* before anything is answered. The only thing lost above the cap is the error message on a file Immich
|
||||
* rejects — and an upload that size which Immich rejects fails either way. Refusing it outright would
|
||||
* break the legitimate case to improve the diagnosis of the doomed one.
|
||||
*/
|
||||
async function readBodyCapped(
|
||||
req: Request,
|
||||
): Promise<{ ok: true; bytes: Uint8Array<ArrayBuffer> } | { ok: false; seen: number }> {
|
||||
// Decided from `content-length` alone. Officer sends one whenever IT buffered, so the two hops agree
|
||||
// without coordinating: a body small enough for officer to hold is small enough to hold here. When the
|
||||
// header is absent officer streamed, which means it was over the cap there too.
|
||||
const declared = Number(req.headers.get('content-length') ?? '');
|
||||
if (!Number.isFinite(declared) || declared <= 0 || declared > MAX_BUFFERED_BODY) return { ok: false, seen: declared };
|
||||
|
||||
const reader = req.body!.getReader();
|
||||
const chunks: Uint8Array[] = [];
|
||||
let total = 0;
|
||||
for (;;) {
|
||||
const { done, value } = await reader.read();
|
||||
if (done) break;
|
||||
total += value.length;
|
||||
if (total > MAX_BUFFERED_BODY) {
|
||||
await reader.cancel().catch(() => {});
|
||||
return { ok: false, seen: total };
|
||||
}
|
||||
chunks.push(value);
|
||||
}
|
||||
|
||||
const bytes = new Uint8Array(new ArrayBuffer(total));
|
||||
let at = 0;
|
||||
for (const chunk of chunks) {
|
||||
bytes.set(chunk, at);
|
||||
at += chunk.length;
|
||||
}
|
||||
return { ok: true, bytes };
|
||||
}
|
||||
|
||||
/**
|
||||
* Forward one request to Immich and stream the answer back.
|
||||
*
|
||||
* The body is a stream, never an ArrayBuffer: a full-resolution original or a `download/archive` zip is
|
||||
* hundreds of megabytes and buffering it would hold all of it in the sidecar's heap for no reason.
|
||||
* The RESPONSE is still a stream, never an ArrayBuffer: a full-resolution original or a
|
||||
* `download/archive` zip is hundreds of megabytes and buffering it would hold all of it in the
|
||||
* sidecar's heap for no reason. Only the request body is held, and only for the reason above.
|
||||
*/
|
||||
export async function handleOfficerRoute(cfg: UpstreamConfig, req: Request, url: URL): Promise<Response | null> {
|
||||
const rest = url.pathname.slice('/_officer/'.length);
|
||||
@@ -109,12 +184,20 @@ export async function handleOfficerRoute(cfg: UpstreamConfig, req: Request, url:
|
||||
query.delete('token');
|
||||
const search = query.toString();
|
||||
|
||||
// Buffered, not streamed — see readBodyCapped. A body that is still being written when Immich answers
|
||||
// loses the answer, which is what made every large upload fail with an unexplained empty 400.
|
||||
let body: BodyInit | null = null;
|
||||
if (hasBody && req.body) {
|
||||
const read = await readBodyCapped(req);
|
||||
// Over the cap (or no declared length): stream it, exactly as this always did. Not an error.
|
||||
body = read.ok ? read.bytes : req.body;
|
||||
}
|
||||
|
||||
const res = await callUpstream(cfg, {
|
||||
path: `/api/${rest}`,
|
||||
method: req.method,
|
||||
query: search ? `?${search}` : '',
|
||||
// Streamed, not buffered: an asset upload can be gigabytes and this layer never reads the bytes.
|
||||
body: hasBody ? req.body : null,
|
||||
body,
|
||||
contentType: req.headers.get('content-type'),
|
||||
range: req.headers.get('range'),
|
||||
ifNoneMatch: req.headers.get('if-none-match'),
|
||||
|
||||
@@ -165,12 +165,15 @@ type CallOptions = {
|
||||
/** Raw search string including the leading `?`, or empty. */
|
||||
query?: string;
|
||||
/**
|
||||
* A string for the JSON callers, or the caller's own request body as a STREAM for the two forwarders.
|
||||
* A string for the JSON callers, or the forwarder's already-buffered request body.
|
||||
*
|
||||
* Streamed rather than buffered because a phone's video upload is bounded by `maxRequestBodySize`
|
||||
* (4 GB) and buffering put all of it in this process's heap for a hop that never looks at the bytes.
|
||||
* Streaming to Immich means chunked transfer-encoding instead of Content-Length — which is already how
|
||||
* the body reaches us, since the platform proxy forwards no content-length either.
|
||||
* This used to be a stream, for the obvious reason that a phone's video should not sit in this
|
||||
* process's heap. It was changed back deliberately: a request body still being written when Immich
|
||||
* answers loses the answer entirely — Node replaces the app's response with a bodyless 400 and closes
|
||||
* — which is what made every large upload fail inexplicably. `readBodyCapped` in routes.ts has the
|
||||
* measurements and the alternatives that were tried; the heap cost is the accepted price.
|
||||
*
|
||||
* A buffer also carries a Content-Length, so the request to Immich is no longer chunked.
|
||||
*/
|
||||
body?: BodyInit | null;
|
||||
contentType?: string | null;
|
||||
|
||||
Reference in New Issue
Block a user