Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions .env.example
Original file line number Diff line number Diff line change
Expand Up @@ -100,6 +100,9 @@ EXAMPLE_USER_PASSWORD='EXAMPLE_123!'
DEFERRED_RESPONSE_ENABLED='false'
# DEFERRED_RESPONSE_THRESHOLD_MS='75000'
# DEFERRED_RESPONSE_KEEPALIVE_MS='25000'
# Backstop for a silent upstream — stops keepalives and returns an error body.
# Measured from when the request arrived, so it can be compared directly against upstream timeouts.
# DEFERRED_RESPONSE_MAX_DURATION_MS='600000'

# Set to true to enable test endpoints (e.g. /api/test/deferred-response)
# ENABLE_TEST_ENDPOINTS='false'
Expand Down
6 changes: 6 additions & 0 deletions apps/api/src/app/types/route.types.ts
Original file line number Diff line number Diff line change
Expand Up @@ -35,8 +35,14 @@ export type Request<
*/
export interface DeferredResponseState {
active: boolean;
/**
* The max duration backstop gave up on the upstream and ended the response. The controller may still
* finish afterwards and try to respond — that is expected here, not an unhandled response.
*/
abandoned: boolean;
timer: NodeJS.Timeout | null;
keepaliveInterval: NodeJS.Timeout | null;
maxDurationTimer: NodeJS.Timeout | null;
startTime: number;
keepaliveCount: number;
}
Expand Down
116 changes: 116 additions & 0 deletions apps/api/src/app/utils/__tests__/deferred-response.middleware.spec.ts
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ vi.mock('@jetstream/api-config', () => ({
DEFERRED_RESPONSE_ENABLED: true,
DEFERRED_RESPONSE_THRESHOLD_MS: 75_000,
DEFERRED_RESPONSE_KEEPALIVE_MS: 25_000,
DEFERRED_RESPONSE_MAX_DURATION_MS: 600_000,
},
getLogger: () => loggerHolder.current,
}));
Expand Down Expand Up @@ -307,8 +308,10 @@ describe('writeDeferredResponse', () => {
const res = createMockRes();
const deferred: DeferredResponseState = {
active: true,
abandoned: false,
timer: null,
keepaliveInterval: null,
maxDurationTimer: null,
startTime: Date.now() - 50_000,
keepaliveCount: 2,
};
Expand All @@ -327,8 +330,10 @@ describe('writeDeferredResponse', () => {
const res = createMockRes();
const deferred: DeferredResponseState = {
active: true,
abandoned: false,
timer: null,
keepaliveInterval: null,
maxDurationTimer: null,
startTime: Date.now() - 60_000,
keepaliveCount: 3,
};
Expand All @@ -350,8 +355,10 @@ describe('writeDeferredResponse', () => {
});
const deferred: DeferredResponseState = {
active: true,
abandoned: false,
timer: null,
keepaliveInterval: null,
maxDurationTimer: null,
startTime: Date.now() - 50_000,
keepaliveCount: 2,
};
Expand All @@ -372,8 +379,10 @@ describe('writeDeferredResponse', () => {
const res = createMockRes();
const deferred: DeferredResponseState = {
active: true,
abandoned: false,
timer: null,
keepaliveInterval: null,
maxDurationTimer: null,
startTime: Date.now() - 50_000,
keepaliveCount: 2,
};
Expand Down Expand Up @@ -405,8 +414,10 @@ describe('writeDeferredResponse', () => {
});
const deferred: DeferredResponseState = {
active: true,
abandoned: false,
timer: null,
keepaliveInterval: null,
maxDurationTimer: null,
startTime: Date.now() - 50_000,
keepaliveCount: 2,
};
Expand All @@ -430,8 +441,10 @@ describe('writeDeferredResponse', () => {
});
const deferred: DeferredResponseState = {
active: true,
abandoned: false,
timer: null,
keepaliveInterval: null,
maxDurationTimer: null,
startTime: Date.now() - 50_000,
keepaliveCount: 2,
};
Expand All @@ -449,10 +462,13 @@ describe('writeDeferredResponse', () => {
const res = createMockRes();
const timer = setTimeout(() => {}, 10_000);
const interval = setInterval(() => {}, 5_000);
const maxDurationTimer = setTimeout(() => {}, 600_000);
const deferred: DeferredResponseState = {
active: true,
abandoned: false,
timer,
keepaliveInterval: interval,
maxDurationTimer,
startTime: Date.now() - 50_000,
keepaliveCount: 2,
};
Expand All @@ -462,15 +478,18 @@ describe('writeDeferredResponse', () => {

expect(deferred.timer).toBeNull();
expect(deferred.keepaliveInterval).toBeNull();
expect(deferred.maxDurationTimer).toBeNull();
vi.useRealTimers();
});

it('should log COMPLETE when the response stream emits finish', () => {
const res = createMockRes();
const deferred: DeferredResponseState = {
active: true,
abandoned: false,
timer: null,
keepaliveInterval: null,
maxDurationTimer: null,
startTime: Date.now() - 50_000,
keepaliveCount: 2,
};
Expand All @@ -487,8 +506,10 @@ describe('writeDeferredResponse', () => {
const res = createMockRes();
const deferred: DeferredResponseState = {
active: true,
abandoned: false,
timer: null,
keepaliveInterval: null,
maxDurationTimer: null,
startTime: Date.now() - 50_000,
keepaliveCount: 2,
};
Expand All @@ -505,8 +526,10 @@ describe('writeDeferredResponse', () => {
const res = createMockRes();
const deferred: DeferredResponseState = {
active: true,
abandoned: false,
timer: null,
keepaliveInterval: null,
maxDurationTimer: null,
startTime: Date.now() - 50_000,
keepaliveCount: 2,
};
Expand All @@ -521,6 +544,99 @@ describe('writeDeferredResponse', () => {
});
});

describe('deferred response max duration backstop', () => {
beforeEach(() => {
vi.useFakeTimers();
});

afterEach(() => {
vi.useRealTimers();
vi.restoreAllMocks();
});

it('should abandon the response with an error body once max duration elapses', () => {
const req = createMockReq();
const res = createMockRes();

// eslint-disable-next-line @typescript-eslint/no-explicit-any
deferredResponseMiddleware(req as any, res as any, vi.fn());
vi.advanceTimersByTime(75_000);
expect((res.locals._deferred as DeferredResponseState).active).toBe(true);

vi.advanceTimersByTime(600_000);

expect(res.log.error).toHaveBeenCalledWith(expect.any(Object), expect.stringContaining('[DEFERRED][MAX_DURATION]'));
expect(res._ended()).toBe(true);

// Headers were locked at 200 when deferring, so the failure has to arrive in the body.
const body = JSON.parse(res._chunks.join(''));
expect(body).toMatchObject({ error: true, success: false });
expect(body.message).toContain('may still have been applied');
});

it('should measure max duration from when the request arrived, not from when it was deferred', () => {
const req = createMockReq();
const res = createMockRes();

// eslint-disable-next-line @typescript-eslint/no-explicit-any
deferredResponseMiddleware(req as any, res as any, vi.fn());
vi.advanceTimersByTime(75_000);

// One tick short of the 600s total budget, so the 75s already spent has to have been subtracted.
vi.advanceTimersByTime(524_999);
expect(res._ended()).toBe(false);

vi.advanceTimersByTime(1);
expect(res._ended()).toBe(true);
});

it('should flag the response as abandoned so a late controller response is not reported as unhandled', () => {
const req = createMockReq();
const res = createMockRes();

// eslint-disable-next-line @typescript-eslint/no-explicit-any
deferredResponseMiddleware(req as any, res as any, vi.fn());
vi.advanceTimersByTime(75_000);
expect((res.locals._deferred as DeferredResponseState).abandoned).toBe(false);

vi.advanceTimersByTime(600_000);

expect((res.locals._deferred as DeferredResponseState).abandoned).toBe(true);
expect((res.locals._deferred as DeferredResponseState).active).toBe(false);
});

it('should not fire once the controller has produced a response', () => {
const req = createMockReq();
const res = createMockRes();

// eslint-disable-next-line @typescript-eslint/no-explicit-any
deferredResponseMiddleware(req as any, res as any, vi.fn());
vi.advanceTimersByTime(75_000);
// eslint-disable-next-line @typescript-eslint/no-explicit-any
writeDeferredResponse(res as any, { data: 'real result' });

vi.advanceTimersByTime(600_000);

expect(res.log.error).not.toHaveBeenCalledWith(expect.any(Object), expect.stringContaining('[DEFERRED][MAX_DURATION]'));
expect(JSON.parse(res._chunks.join(''))).toEqual({ data: 'real result' });
});

it('should stop keepalives so the socket cannot be held indefinitely', () => {
const req = createMockReq();
const res = createMockRes();

// eslint-disable-next-line @typescript-eslint/no-explicit-any
deferredResponseMiddleware(req as any, res as any, vi.fn());
vi.advanceTimersByTime(75_000);
vi.advanceTimersByTime(600_000);

const chunkCountAfterAbandon = res._chunks.length;
vi.advanceTimersByTime(300_000);

expect(res._chunks.length).toBe(chunkCountAfterAbandon);
});
});

describe('JSON.parse with space-padded response', () => {
it('should parse JSON with leading spaces (simulating chunked keepalive)', () => {
const originalJson = '{"data":{"message":"hello"}}';
Expand Down
48 changes: 48 additions & 0 deletions apps/api/src/app/utils/__tests__/error-handler.spec.ts
Original file line number Diff line number Diff line change
@@ -0,0 +1,48 @@
import { ERROR_MESSAGES } from '@jetstream/shared/constants';
import { describe, expect, it, vi } from 'vitest';
import { UserFacingError } from '../error-handler';

vi.mock('@jetstream/api-config', () => ({
logger: { warn: vi.fn(), error: vi.fn(), info: vi.fn(), debug: vi.fn() },
}));

/** Shape Node/undici produces: an opaque TypeError with the real reason hanging off `cause`. */
function buildFetchFailure(code?: string) {
const error = new TypeError('fetch failed');
error.cause = code ? Object.assign(new Error('upstream blew up'), { code }) : undefined;
return error;
}

describe('UserFacingError upstream fetch failures', () => {
it('replaces an undici headers timeout with copy that does not claim the operation failed', () => {
const error = new UserFacingError(buildFetchFailure('UND_ERR_HEADERS_TIMEOUT'));

expect(error.message).toBe(ERROR_MESSAGES.SFDC_UPSTREAM_TIMEOUT);
expect(error.message).not.toContain('fetch failed');
// The whole point: the write may have landed, so the user must check before retrying.
expect(error.message).toContain('may still have been applied');
});

it('treats UND_ERR_BODY_TIMEOUT as a timeout', () => {
expect(new UserFacingError(buildFetchFailure('UND_ERR_BODY_TIMEOUT')).message).toBe(ERROR_MESSAGES.SFDC_UPSTREAM_TIMEOUT);
});

// A connect timeout means the request never reached Salesforce, so nothing can have been applied
// and the user should just retry — the opposite of what the timeout copy tells them to do.
it.each(['ECONNRESET', 'UND_ERR_CONNECT_TIMEOUT'])('reports %s as unreachable rather than as a timeout', (code) => {
expect(new UserFacingError(buildFetchFailure(code)).message).toBe(ERROR_MESSAGES.SFDC_UPSTREAM_UNREACHABLE);
});

it('reports a fetch failure with no cause as unreachable rather than leaking the raw message', () => {
expect(new UserFacingError(buildFetchFailure()).message).toBe(ERROR_MESSAGES.SFDC_UPSTREAM_UNREACHABLE);
});

it('leaves unrelated errors untouched', () => {
expect(new UserFacingError(new Error('Required field missing')).message).toBe('Required field missing');
expect(new UserFacingError('A plain string message').message).toBe('A plain string message');
});

it('still scrubs raw XML error bodies', () => {
expect(new UserFacingError(new Error('<?xml version="1.0"?><Errors />')).message).toBe('An unexpected error has occurred');
});
});
50 changes: 48 additions & 2 deletions apps/api/src/app/utils/deferred-response.middleware.ts
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
import { ENV, getLogger } from '@jetstream/api-config';
import { HTTP } from '@jetstream/shared/constants';
import { ERROR_MESSAGES, HTTP } from '@jetstream/shared/constants';
import type { Response as ExpressResponse, NextFunction, Request } from 'express';
import type { DeferredResponseState, Response } from '../types/route.types';
import { setCookieHeaders } from './response.handlers';
Expand All @@ -9,11 +9,16 @@ export type { DeferredResponseState };
/**
* Middleware that prevents Cloudflare 524 timeouts for long-running Salesforce API requests.
*
* When a response takes longer than the threshold (default 45s), the middleware begins
* When a response takes longer than the threshold (default 75s), the middleware begins
* streaming space characters as chunked keepalive bytes. When the actual response is ready,
* it is written to the stream. JSON.parse natively ignores leading whitespace, so Axios
* on the client handles this transparently.
*
* Keepalives stop DEFERRED_RESPONSE_MAX_DURATION_MS (default 10m) after the request arrived, which
* bounds how long a silent upstream can hold a socket open. That is a backstop, not the normal path —
* it sits well above undici's 300s headersTimeout, which is what actually ends most stalled
* Salesforce calls.
*
* NOTE: If compression middleware is re-enabled, chunks may be buffered and not flushed
* to Cloudflare in time. This middleware requires compression to be disabled.
*/
Expand All @@ -24,8 +29,10 @@ export function deferredResponseMiddleware(req: Request, res: Response, next: Ne

const deferred: DeferredResponseState = {
active: false,
abandoned: false,
timer: null,
keepaliveInterval: null,
maxDurationTimer: null,
startTime: Date.now(),
keepaliveCount: 0,
};
Expand Down Expand Up @@ -80,6 +87,41 @@ export function deferredResponseMiddleware(req: Request, res: Response, next: Ne
return;
}

// Backstop: without this the keepalive loop runs for as long as upstream stays silent, holding
// a socket open long after the client (and Cloudflare) have given up. Salesforce calls made via
// fetch are bounded by undici's 300s headersTimeout, but nothing bounds the other paths.
// The budget is measured from when the request arrived rather than from now, so the configured
// value can be compared directly against Cloudflare and load balancer timeouts. The floor keeps
// a max duration set below the threshold from producing a zero delay.
const maxDurationMs = Number(ENV.DEFERRED_RESPONSE_MAX_DURATION_MS) || 600_000;
deferred.maxDurationTimer = setTimeout(
() => {
if (!deferred.active || res.writableEnded) {
return;
}
getLogger().error(
{
method: req.method,
url: req.originalUrl,
elapsedMs: Date.now() - deferred.startTime,
keepaliveCount: deferred.keepaliveCount,
},
'[DEFERRED][MAX_DURATION] Upstream never responded, abandoning deferred response',
);
// Flagged before the write so that when the controller eventually finishes, sendJson and the
// error handler can tell this apart from a genuinely unhandled response.
deferred.abandoned = true;
// Headers were committed as 200 when the response was deferred, so the failure has to be
// reported in the body — same envelope the error handler writes.
writeDeferredResponse(res, {
error: true,
success: false,
message: ERROR_MESSAGES.SFDC_UPSTREAM_TIMEOUT,
});
},
Math.max(maxDurationMs - elapsedMs, 1_000),
);

// Start periodic keepalive
deferred.keepaliveInterval = setInterval(
() => {
Expand Down Expand Up @@ -231,6 +273,10 @@ export function clearDeferredTimers(deferred: DeferredResponseState) {
clearInterval(deferred.keepaliveInterval);
deferred.keepaliveInterval = null;
}
if (deferred.maxDurationTimer) {
clearTimeout(deferred.maxDurationTimer);
deferred.maxDurationTimer = null;
}
}

function cleanupDeferred(deferred: DeferredResponseState) {
Expand Down
Loading
Loading