Skip to content

Commit 706ed8b

Browse files
habdelraclaude
andcommitted
Whitelist the correlation header for CORS, rename it, and fix coalesced-search timing
- CORS: add the correlation header to the realm-server's `Access-Control-Allow-Headers` allowlist. Without it the cross-origin preflight blocks the prerender's `_federated-search` once the host stamps the header. - Rename `x-boxel-request-id` → `x-boxel-logging-correlation-id` (and the internal field/vars to `loggingCorrelationId`, the log token to `corr=`): the old name read too much like the unrelated `x-boxel-client-request-id`, which is realm-event/write correlation, a different concern. - searchCards in-flight coalescing: exclude the per-request `timings` collector from `searchInFlightKey` so it can't perturb the dedup key, and when a follower awaits an already-running identical search, record that wait as `coalescedWait` on the follower's own collector — otherwise its timing line would show no sql/loadLinks and look misleadingly instant under concurrent search load. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent 498aab2 commit 706ed8b

10 files changed

Lines changed: 71 additions & 46 deletions

File tree

packages/host/app/lib/prerender-fetch-headers.ts

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,7 @@ import {
22
DURING_PRERENDER_HEADER,
33
X_BOXEL_CONSUMING_REALM_HEADER,
44
X_BOXEL_JOB_ID_HEADER,
5-
X_BOXEL_REQUEST_ID_HEADER,
5+
X_BOXEL_LOGGING_CORRELATION_ID_HEADER,
66
} from '@cardstack/runtime-common';
77

88
// Set by the prerender server's `evaluateOnNewDocument` before the
@@ -50,19 +50,19 @@ export function jobIdHeader(): Record<string, string> {
5050

5151
// Per-search correlation id. Minted fresh for each `_federated-search`
5252
// fetch the SPA issues while rendering inside a prerender tab, and stamped
53-
// as `x-boxel-request-id`. The realm-server reads it back out and keys its
53+
// as `x-boxel-logging-correlation-id`. The realm-server reads it back out and keys its
5454
// `realm:search-timing` line on it, so a search the prerender observes as
5555
// slow (surfaced in its `queryLoadsInFlight` diagnostics) can be joined to
5656
// the realm-server's stage-by-stage view of the same request. Gated on the
5757
// prerender context — exactly like the job-id / consuming-realm headers —
5858
// so live SPA traffic is unaffected and emits no server-side timing line.
59-
export function requestIdHeader(): Record<string, string> {
59+
export function loggingCorrelationIdHeader(): Record<string, string> {
6060
let flag = (globalThis as unknown as { __boxelRenderContext?: boolean })
6161
.__boxelRenderContext;
6262
if (flag !== true) {
6363
return {};
6464
}
65-
return { [X_BOXEL_REQUEST_ID_HEADER]: newCorrelationId() };
65+
return { [X_BOXEL_LOGGING_CORRELATION_ID_HEADER]: newCorrelationId() };
6666
}
6767

6868
function newCorrelationId(): string {

packages/host/app/services/store.ts

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -89,7 +89,7 @@ import {
8989
consumingRealmHeader,
9090
duringPrerenderHeaders,
9191
jobIdHeader,
92-
requestIdHeader,
92+
loggingCorrelationIdHeader,
9393
} from '../lib/prerender-fetch-headers';
9494
import { searchCacheKey } from '../lib/search-cache-key';
9595
import { searchInFlightKey } from '../lib/search-in-flight-key';
@@ -1154,7 +1154,7 @@ export default class StoreService extends Service implements StoreInterface {
11541154
...consumingRealmHeader(),
11551155
...jobIdHeader(),
11561156
...jobPriorityHeader(),
1157-
...requestIdHeader(),
1157+
...loggingCorrelationIdHeader(),
11581158
},
11591159
body: JSON.stringify({ ...query, realms }),
11601160
},

packages/host/tests/helpers/realm-server-mock/routes.ts

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -7,11 +7,11 @@ import {
77
parseSearchQueryFromPayload,
88
parseSearchRequestPayload,
99
SearchRequestError,
10-
sanitizeRequestId,
10+
sanitizeLoggingCorrelationId,
1111
searchPrerenderedRealms,
1212
searchRealms,
1313
SupportedMimeType,
14-
X_BOXEL_REQUEST_ID_HEADER,
14+
X_BOXEL_LOGGING_CORRELATION_ID_HEADER,
1515
type RealmInfo,
1616
type Query,
1717
} from '@cardstack/runtime-common';
@@ -124,13 +124,13 @@ function registerSearchRoutes() {
124124
// correlation id off the request and thread it into searchRealms, so
125125
// the real `realm:search-timing` line is emitted (and observable by
126126
// host integration tests) keyed by the id the client minted.
127-
let requestId = sanitizeRequestId(
128-
req.headers.get(X_BOXEL_REQUEST_ID_HEADER),
127+
let loggingCorrelationId = sanitizeLoggingCorrelationId(
128+
req.headers.get(X_BOXEL_LOGGING_CORRELATION_ID_HEADER),
129129
);
130130
let combined = await searchRealms(
131131
realmList.map((realmURL) => getSearchableRealmForURL(realmURL)),
132132
cardsQuery,
133-
requestId ? { requestId } : undefined,
133+
loggingCorrelationId ? { loggingCorrelationId } : undefined,
134134
);
135135

136136
return new Response(JSON.stringify(combined), {

packages/host/tests/integration/search-correlation-id-test.gts

Lines changed: 9 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@ import {
88
baseRealm,
99
rri,
1010
setSearchTimingSinkForTests,
11-
X_BOXEL_REQUEST_ID_HEADER,
11+
X_BOXEL_LOGGING_CORRELATION_ID_HEADER,
1212
} from '@cardstack/runtime-common';
1313
import type { Loader } from '@cardstack/runtime-common/loader';
1414
import type { Query } from '@cardstack/runtime-common/query';
@@ -26,14 +26,14 @@ import { setupMockMatrix } from '../helpers/mock-matrix';
2626
import { setupRenderingTest } from '../helpers/setup';
2727

2828
// End-to-end coverage for the search correlation id: the in-realm browser
29-
// (the prerendered host SPA) mints `x-boxel-request-id` on its
29+
// (the prerendered host SPA) mints `x-boxel-logging-correlation-id` on its
3030
// `_federated-search` fetch, and the realm-server's search path emits a
3131
// `realm:search-timing` line keyed by that same id. This proves the id
3232
// threads all the way from the client that originated it through to the
3333
// server log a triage would join against.
3434
//
3535
// The host test exercises the *real* code on both ends: the SPA's
36-
// `requestIdHeader()` stamps the header, and the realm-server-mock hands it
36+
// `loggingCorrelationIdHeader()` stamps the header, and the realm-server-mock hands it
3737
// to the real `searchRealms`, which emits the line. Only the prerender
3838
// context flag is simulated (the host normally sets it inside a prerender
3939
// tab).
@@ -108,7 +108,7 @@ module('Integration | search correlation id', function (hooks) {
108108
let sentRequestIds: string[] = [];
109109
let spy = async (request: Request) => {
110110
if (new URL(request.url).pathname.endsWith('/_federated-search')) {
111-
let id = request.headers.get(X_BOXEL_REQUEST_ID_HEADER);
111+
let id = request.headers.get(X_BOXEL_LOGGING_CORRELATION_ID_HEADER);
112112
if (id) {
113113
sentRequestIds.push(id);
114114
}
@@ -139,7 +139,9 @@ module('Integration | search correlation id', function (hooks) {
139139
`client-minted correlation id looks well-formed (${sentId})`,
140140
);
141141

142-
let matching = timingLines.filter((line) => line.includes(`req=${sentId}`));
142+
let matching = timingLines.filter((line) =>
143+
line.includes(`corr=${sentId}`),
144+
);
143145
assert.strictEqual(
144146
matching.length,
145147
1,
@@ -168,7 +170,7 @@ module('Integration | search correlation id', function (hooks) {
168170
let spy = async (request: Request) => {
169171
if (
170172
new URL(request.url).pathname.endsWith('/_federated-search') &&
171-
request.headers.get(X_BOXEL_REQUEST_ID_HEADER)
173+
request.headers.get(X_BOXEL_LOGGING_CORRELATION_ID_HEADER)
172174
) {
173175
sawHeader = true;
174176
}
@@ -184,7 +186,7 @@ module('Integration | search correlation id', function (hooks) {
184186
assert.strictEqual(results.length, 2, 'the search still returns results');
185187
assert.false(
186188
sawHeader,
187-
'live (non-prerender) traffic sends no x-boxel-request-id header',
189+
'live (non-prerender) traffic sends no x-boxel-logging-correlation-id header',
188190
);
189191
assert.strictEqual(
190192
timingLines.length,

packages/realm-server/handlers/handle-search.ts

Lines changed: 12 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -10,8 +10,8 @@ import {
1010
sanitizeConsumingRealmHeader,
1111
SearchRequestError,
1212
searchRealms,
13-
sanitizeRequestId,
14-
X_BOXEL_REQUEST_ID_HEADER,
13+
sanitizeLoggingCorrelationId,
14+
X_BOXEL_LOGGING_CORRELATION_ID_HEADER,
1515
RequestTimings,
1616
emitSearchTiming,
1717
} from '@cardstack/runtime-common';
@@ -47,8 +47,11 @@ export default function handleSearch(opts: {
4747
// outermost request→response bound (incl. body read + send) is the
4848
// `realm:requests` middleware's `dur=`, keyed by the same id.
4949
let handlerStart = Date.now();
50-
let requestId = sanitizeRequestId(ctxt.get(X_BOXEL_REQUEST_ID_HEADER));
51-
let timings = requestId !== null ? new RequestTimings() : undefined;
50+
let loggingCorrelationId = sanitizeLoggingCorrelationId(
51+
ctxt.get(X_BOXEL_LOGGING_CORRELATION_ID_HEADER),
52+
);
53+
let timings =
54+
loggingCorrelationId !== null ? new RequestTimings() : undefined;
5255

5356
let { realmList } = getMultiRealmAuthorization(ctxt);
5457

@@ -123,18 +126,18 @@ export default function handleSearch(opts: {
123126
if (prerenderJobId) searchOpts.jobIdentity = prerenderJobId;
124127
let normalizedSearchOpts =
125128
Object.keys(searchOpts).length > 0 ? searchOpts : undefined;
126-
// `requestId` / `timings` are deliberately kept OUT of `searchOpts`:
129+
// `loggingCorrelationId` / `timings` are deliberately kept OUT of `searchOpts`:
127130
// that object is the job-scoped search cache's key material (see
128131
// `computeETag` / `getOrPopulate` below), and per-request values would
129132
// make every key unique and defeat the cache. They only need to reach
130133
// `searchRealms` (which stamps the SQL + loadLinks stages onto the same
131134
// collector this handler emits), so they ride on the run-time opts and
132135
// never touch the cache key.
133136
let runSearchOpts =
134-
requestId !== null
137+
loggingCorrelationId !== null
135138
? {
136139
...(normalizedSearchOpts ?? {}),
137-
requestId,
140+
loggingCorrelationId,
138141
...(timings ? { timings } : {}),
139142
}
140143
: normalizedSearchOpts;
@@ -168,11 +171,11 @@ export default function handleSearch(opts: {
168171
// error early returns above, which never reach here). No-op without a
169172
// correlation id.
170173
let emitTimeline = () => {
171-
if (!timings || requestId === null) {
174+
if (!timings || loggingCorrelationId === null) {
172175
return;
173176
}
174177
emitSearchTiming(
175-
`req=${requestId}` +
178+
`corr=${loggingCorrelationId}` +
176179
(prerenderJobId ? ` job=${prerenderJobId}` : '') +
177180
` handler=${Date.now() - handlerStart}ms ` +
178181
timings.toLogFragment(),

packages/realm-server/middleware/index.ts

Lines changed: 10 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -4,8 +4,8 @@ import type { ResponseWithNodeStream } from '@cardstack/runtime-common';
44
import {
55
logger as getLogger,
66
webStreamToText,
7-
sanitizeRequestId,
8-
X_BOXEL_REQUEST_ID_HEADER,
7+
sanitizeLoggingCorrelationId,
8+
X_BOXEL_LOGGING_CORRELATION_ID_HEADER,
99
} from '@cardstack/runtime-common';
1010
import type Koa from 'koa';
1111
import mime from 'mime-types';
@@ -173,10 +173,12 @@ export function httpLogging(ctxt: Koa.Context, next: Koa.Next) {
173173
// joins to the realm-server's view of the same request. The matching
174174
// `realm:search-timing` line (emitted by `searchRealms`) is keyed by the
175175
// same value.
176-
let requestId = sanitizeRequestId(ctxt.get(X_BOXEL_REQUEST_ID_HEADER));
177-
let reqTag = requestId ? ` req=${requestId}` : '';
178-
if (requestId) {
179-
ctxt.set(X_BOXEL_REQUEST_ID_HEADER, requestId);
176+
let loggingCorrelationId = sanitizeLoggingCorrelationId(
177+
ctxt.get(X_BOXEL_LOGGING_CORRELATION_ID_HEADER),
178+
);
179+
let corrTag = loggingCorrelationId ? ` corr=${loggingCorrelationId}` : '';
180+
if (loggingCorrelationId) {
181+
ctxt.set(X_BOXEL_LOGGING_CORRELATION_ID_HEADER, loggingCorrelationId);
180182
}
181183
let startedAt = Date.now();
182184

@@ -199,7 +201,7 @@ export function httpLogging(ctxt: Koa.Context, next: Koa.Next) {
199201
logger.info(
200202
`<-- ${ctxt.method} ${ctxt.req.headers.accept} ${
201203
fullRequestURL(ctxt).href
202-
}${jobTag}${reqTag}`,
204+
}${jobTag}${corrTag}`,
203205
);
204206

205207
let onSettled = () => {
@@ -209,7 +211,7 @@ export function httpLogging(ctxt: Koa.Context, next: Koa.Next) {
209211
logger.info(
210212
`--> ${ctxt.method} ${ctxt.req.headers.accept} ${
211213
fullRequestURL(ctxt).href
212-
}: ${ctxt.status}${jobTag}${reqTag} dur=${Date.now() - startedAt}ms`,
214+
}: ${ctxt.status}${jobTag}${corrTag} dur=${Date.now() - startedAt}ms`,
213215
);
214216
logger.debug(JSON.stringify(ctxt.req.headers));
215217
};

packages/realm-server/server.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -728,7 +728,7 @@ export class RealmServer {
728728
cors({
729729
origin: '*',
730730
allowHeaders:
731-
'Authorization, Content-Type, If-Match, If-None-Match, X-Requested-With, X-Boxel-Client-Request-Id, X-Boxel-Assume-User, X-HTTP-Method-Override, X-Boxel-Disable-Module-Cache, X-Filename, X-Boxel-During-Prerender, X-Boxel-Consuming-Realm, X-Boxel-Job-Id, X-Boxel-Job-Priority, X-Grafana-Device-Id, X-Grafana-Action',
731+
'Authorization, Content-Type, If-Match, If-None-Match, X-Requested-With, X-Boxel-Client-Request-Id, X-Boxel-Assume-User, X-HTTP-Method-Override, X-Boxel-Disable-Module-Cache, X-Filename, X-Boxel-During-Prerender, X-Boxel-Consuming-Realm, X-Boxel-Job-Id, X-Boxel-Job-Priority, X-Boxel-Logging-Correlation-Id, X-Grafana-Device-Id, X-Grafana-Action',
732732
// Without an explicit expose list, @koa/cors only emits the
733733
// CORS-safelisted response headers (cache-control, content-*,
734734
// expires, last-modified, pragma). ETag is not on that list,

packages/runtime-common/prerender-headers.ts

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -102,14 +102,15 @@ export function sanitizeJobPriorityHeader(
102102
// can be joined to where the realm-server actually spent the time. Lives
103103
// here so the host SPA can import the header name without depending on
104104
// the realm-server package.
105-
export const X_BOXEL_REQUEST_ID_HEADER = 'x-boxel-request-id';
105+
export const X_BOXEL_LOGGING_CORRELATION_ID_HEADER =
106+
'x-boxel-logging-correlation-id';
106107

107108
// Sanitize the inbound request-id header. It's echoed into log lines, so
108109
// admit only a bounded run of URL-safe id characters (covers a UUID and
109110
// then some) and reject anything with whitespace or control characters
110111
// that could forge a log line.
111112
const REQUEST_ID_PATTERN = /^[A-Za-z0-9._:-]{1,128}$/;
112-
export function sanitizeRequestId(
113+
export function sanitizeLoggingCorrelationId(
113114
raw: string | null | undefined,
114115
): string | null {
115116
if (typeof raw !== 'string') return null;

packages/runtime-common/realm-index-query-engine.ts

Lines changed: 19 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -227,10 +227,19 @@ export function searchInFlightKey(
227227
// values inside query/opts — e.g. a `matches: 'a|b'` string — can never
228228
// collide with the delimiter and cause unrelated searches to coalesce.
229229
try {
230+
// `timings` is a per-request diagnostic collector, not part of the
231+
// result-shaping opts. Exclude it from the key so it can't perturb the
232+
// in-flight coalescing — two otherwise-identical searches must still
233+
// dedupe even though each carries its own collector.
234+
let keyOpts = opts;
235+
if (opts && 'timings' in opts) {
236+
let { timings: _omitTimings, ...rest } = opts;
237+
keyOpts = rest;
238+
}
230239
return JSON.stringify([
231240
realmURL,
232241
normalizeQueryForSignature(query),
233-
opts ? sortKeysDeep(opts) : null,
242+
keyOpts ? sortKeysDeep(keyOpts) : null,
234243
]);
235244
} catch {
236245
return undefined;
@@ -341,7 +350,15 @@ export class RealmIndexQueryEngine {
341350
if (key !== undefined) {
342351
let existing = this.#inFlightSearch.get(key);
343352
if (existing) {
344-
return await existing;
353+
// A concurrent identical search is already running; this follower
354+
// awaits its result instead of re-running the work. Record that wait
355+
// as `coalescedWait` on the follower's own collector so its
356+
// `realm:search-timing` line reflects the time spent — otherwise the
357+
// follower would show no `sql`/`loadLinks` and look misleadingly
358+
// instant exactly under the concurrent search load we're diagnosing.
359+
return opts?.timings
360+
? await opts.timings.time('coalescedWait', () => existing)
361+
: await existing;
345362
}
346363
let pending = this.searchCardsUncoalesced(query, opts).finally(() => {
347364
// Identity-check before deletion: a concurrent invalidation path

packages/runtime-common/search-utils.ts

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -329,14 +329,14 @@ export type SearchOpts = {
329329
priority?: number;
330330
jobIdentity?: string;
331331
// Correlation id minted by the client (the prerendered host stamps
332-
// `x-boxel-request-id` on its `_federated-search` fetch) and read back
332+
// `x-boxel-logging-correlation-id` on its `_federated-search` fetch) and read back
333333
// out by the request handler into opts. When present, `searchRealms`
334334
// instruments the server-side search pipeline and emits one
335335
// `realm:search-timing` line keyed by this id, so a client-observed
336336
// slow search can be joined to where the realm-server spent the time.
337-
requestId?: string;
337+
loggingCorrelationId?: string;
338338
// Per-request wall-clock collector. `searchRealms` creates it when a
339-
// `requestId` is present and threads it down through `Realm.search` →
339+
// `loggingCorrelationId` is present and threads it down through `Realm.search` →
340340
// `searchCards` → `loadLinks` so each post-SQL stage stamps its
341341
// elapsed time. Callers never supply this directly.
342342
timings?: RequestTimings;
@@ -384,9 +384,9 @@ export async function searchRealms(
384384
// Two callers: the realm-server's `handle-search` threads a collector it
385385
// owns (so it can emit one complete request→response line itself —
386386
// `opts.timings` is set, `ownsTimings` is false, we don't emit), and the
387-
// host-test realm-server mock calls us with just a `requestId` (we create
387+
// host-test realm-server mock calls us with just a `loggingCorrelationId` (we create
388388
// the collector and emit the line ourselves, which the host test observes).
389-
let ownsTimings = Boolean(opts?.requestId) && !opts?.timings;
389+
let ownsTimings = Boolean(opts?.loggingCorrelationId) && !opts?.timings;
390390
let timings =
391391
opts?.timings ?? (ownsTimings ? new RequestTimings() : undefined);
392392
let perRealmOpts = ownsTimings && opts ? { ...opts, timings } : opts;
@@ -425,7 +425,7 @@ export async function searchRealms(
425425
}
426426
if (ownsTimings && timings) {
427427
emitSearchTiming(
428-
`req=${opts!.requestId}` +
428+
`corr=${opts!.loggingCorrelationId}` +
429429
(opts!.jobIdentity ? ` job=${opts!.jobIdentity}` : '') +
430430
` realms=${realmEntries.length}` +
431431
` total=${Date.now() - startedAt}ms ` +

0 commit comments

Comments
 (0)