Skip to content
Merged
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
7 changes: 7 additions & 0 deletions .changeset/fail-closed-span-customizers.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,7 @@
---
"braintrust": patch
---

fix: fail closed on span customizer errors without dropping records

Preserve original identity, routing, and duration timestamps with `context.customizer_error: true`; strip all other content and prevent attachment uploads. Log safely at most once across SDK bundles, reuse stripped records on retries, and isolate them from merging and masking in ordered export requests.
10 changes: 6 additions & 4 deletions js/src/instrumentation/config.ts
Original file line number Diff line number Diff line change
Expand Up @@ -10,10 +10,12 @@ export interface SpanCustomizer {
* Callbacks are synchronous. Add, change, or delete payload fields, then return
* the record or a replacement plain object. Payloads may still contain SDK
* Attachment objects; attachment processing and serialization happen later.
* Throwing or returning an invalid value (including a promise) logs a safe
* error, stops the callback chain, and drops this outgoing record. Later
* records are evaluated independently; already exported records cannot be
* retracted. Handle recovery inside the callback if export should continue.
* Throwing or returning an invalid value (including a promise) stops the chain
* and exports only original identity, routing, and duration timestamps, plus
* context: { customizer_error: true }. No attachments from that record upload.
* A safe error is logged at most once per JavaScript global environment.
* Later records are evaluated independently; already exported records cannot
* be retracted. Handle recovery inside the callback to retain span content.
*/
onSpanExport?(data: SpanExportData): SpanExportData;
}
Expand Down
160 changes: 97 additions & 63 deletions js/src/logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -47,7 +47,6 @@ import {
LogFeedbackFullArgs,
mergeDicts,
mergeGitMetadataSettings,
mergeRowBatch,
OBJECT_DELETE_FIELD,
OBJECT_ID_KEYS,
SanitizedExperimentLogPartialArgs,
Expand Down Expand Up @@ -210,6 +209,7 @@ import {
import {
createMaskingCustomizer,
customizeSpanExport,
mergeCustomizedSpanRecords,
} from "./span-customizer";
import type { SpanCustomizer, SpanExportData } from "./instrumentation/config";

Expand Down Expand Up @@ -2504,7 +2504,7 @@ function updateSpanImpl({
...updateEvent,
...(await parentIds()),
[IS_MERGE_FIELD]: true,
}) as BackgroundLogEvent | null,
}) as BackgroundLogEvent,
);
state.bgLogger().log([record]);
}
Expand Down Expand Up @@ -3273,7 +3273,7 @@ function getNumericEnv(name: string): number | undefined {
}

interface BackgroundLogger {
log(items: LazyValue<BackgroundLogEvent | null>[]): void;
log(items: LazyValue<BackgroundLogEvent>[]): void;
flush(): Promise<void>;
pendingFlushBytes(): number;
flushBackpressureBytes(): number;
Expand All @@ -3283,10 +3283,10 @@ interface BackgroundLogger {
}

export class TestBackgroundLogger implements BackgroundLogger {
private items: LazyValue<BackgroundLogEvent | null>[][] = [];
private items: LazyValue<BackgroundLogEvent>[][] = [];
private exportCustomizers: readonly SpanCustomizer[] = [];

log(items: LazyValue<BackgroundLogEvent | null>[]): void {
log(items: LazyValue<BackgroundLogEvent>[]): void {
this.items.push(items);
}

Expand Down Expand Up @@ -3318,23 +3318,20 @@ export class TestBackgroundLogger implements BackgroundLogger {
const events: BackgroundLogEvent[] = [];
for (const item of items) {
for (const event of item) {
const value = await event.get();
if (value !== null) events.push(value);
events.push(await event.get());
}
}

let batch = mergeRowBatch(events);
let batch = mergeCustomizedSpanRecords(events).flat();

if (this.exportCustomizers.length) {
batch = batch
.map(
(item) =>
customizeSpanExport(
item as SpanExportData,
this.exportCustomizers,
) as BackgroundLogEvent | null,
)
.filter((item): item is BackgroundLogEvent => item !== null);
batch = batch.map(
(item) =>
customizeSpanExport(
item as SpanExportData,
this.exportCustomizers,
) as BackgroundLogEvent,
);
}

return batch;
Expand Down Expand Up @@ -3427,7 +3424,7 @@ class ConcurrencyLimiter {

interface QueuedLogEvent {
sequence: number;
event: LazyValue<BackgroundLogEvent | null>;
event: LazyValue<BackgroundLogEvent>;
}

class HTTPBackgroundLogger implements BackgroundLogger {
Expand Down Expand Up @@ -3581,7 +3578,7 @@ class HTTPBackgroundLogger implements BackgroundLogger {
return this._flushBackpressureBytes;
}

log(items: LazyValue<BackgroundLogEvent | null>[]) {
log(items: LazyValue<BackgroundLogEvent>[]) {
if (this._disabled) {
return;
}
Expand Down Expand Up @@ -3682,46 +3679,54 @@ class HTTPBackgroundLogger implements BackgroundLogger {
}

private async flushWrappedItemsChunk(
wrappedItems: LazyValue<BackgroundLogEvent | null>[],
wrappedItems: LazyValue<BackgroundLogEvent>[],
batchSize: number,
) {
if (!wrappedItems.length) {
return;
}

const [allItems, attachments] = await this.unwrapLazyValues(wrappedItems);
if (allItems.length === 0) {
return;
}

// Construct batches of records to flush in parallel.
// Failure barriers must be sent in order, in separate requests. Within each
// group, retain the normal parallel transport batching.
let chunkBytes = 0;
const allItemsWithMeta = allItems.map((item) => {
const withMeta = stringifyWithOverflowMeta(item);
chunkBytes += withMeta.str.length;
return withMeta;
});
const groupsWithMeta = allItems.map((group) =>
group.map((item) => {
const withMeta = stringifyWithOverflowMeta(item);
chunkBytes += withMeta.str.length;
return withMeta;
}),
);
this._pendingBytes += chunkBytes;

const maxRequestSizeResult = await this.getMaxRequestSize();
const batches = batchItems({
items: allItemsWithMeta,
batchMaxNumItems: batchSize,
batchMaxNumBytes: maxRequestSizeResult.maxRequestSize / 2,
getByteSize: (item) => item.str.length,
});

const postPromises = batches.map((batch) =>
this.requestLimiter.run(async () => {
try {
await this.submitLogsRequest(batch, maxRequestSizeResult);
return { type: "success" } as const;
} catch (e) {
return { type: "error", value: e } as const;
}
}),
);
const results = await Promise.all(postPromises);
const results: ({ type: "success" } | { type: "error"; value: unknown })[] =
[];
for (const items of groupsWithMeta) {
// Later groups may depend on rows in a failed group, so stop sending.
if (results.some((r) => r.type === "error")) break;
const batches = batchItems({
items,
batchMaxNumItems: batchSize,
batchMaxNumBytes: maxRequestSizeResult.maxRequestSize / 2,
getByteSize: (item) => item.str.length,
});
results.push(
...(await Promise.all(
batches.map((batch) =>
this.requestLimiter.run(async () => {
try {
await this.submitLogsRequest(batch, maxRequestSizeResult);
return { type: "success" } as const;
} catch (e) {
return { type: "error", value: e } as const;
}
}),
),
)),
);
}
this._pendingBytes = Math.max(0, this._pendingBytes - chunkBytes);
const failingResultErrors = results
.map((r) => (r.type === "success" ? undefined : r.value))
Expand Down Expand Up @@ -3756,34 +3761,45 @@ class HTTPBackgroundLogger implements BackgroundLogger {
}

private async unwrapLazyValues(
wrappedItems: LazyValue<BackgroundLogEvent | null>[],
): Promise<[BackgroundLogEvent[], Attachment[]]> {
wrappedItems: LazyValue<BackgroundLogEvent>[],
): Promise<[BackgroundLogEvent[][], Attachment[]]> {
for (let i = 0; i < this.numTries; ++i) {
try {
const items = (
await Promise.all(wrappedItems.map((x) => x.get()))
).filter((item): item is BackgroundLogEvent => item !== null);
const items = await Promise.all(wrappedItems.map((x) => x.get()));

// TODO(kevin): `extractAttachments` should ideally come after
// `mergeRowBatch`, since merge-overwriting could result in some
// attachments that no longer need to be uploaded. This would require
// modifying the merge logic to treat the Attachment object as a "leaf"
// rather than attempting to merge the keys of the Attachment.
const attachments: Attachment[] = [];
let attachments: Attachment[] = [];
items.forEach((item) => extractAttachments(item, attachments));

let mergedItems = mergeRowBatch(items);
let mergedItems = mergeCustomizedSpanRecords(items);

if (this.exportCustomizers.length) {
mergedItems = mergedItems
.map(
mergedItems = mergedItems.map((group) =>
group.map(
(item) =>
customizeSpanExport(
item as SpanExportData,
this.exportCustomizers,
) as BackgroundLogEvent | null,
)
.filter((item): item is BackgroundLogEvent => item !== null);
) as BackgroundLogEvent,
),
);
// Customizers may strip or replace attachment references; don't upload
// content that is no longer referenced by any exported record.
const referencedKeys = new Set<string>();
mergedItems.forEach((group) =>
group.forEach((item) =>
collectAttachmentReferenceKeys(item, referencedKeys),
),
);
attachments = attachments.filter(
(attachment) =>
attachment.reference.type !== BRAINTRUST_ATTACHMENT ||
referencedKeys.has(attachment.reference.key),
);
}

return [mergedItems, attachments];
Expand Down Expand Up @@ -3968,7 +3984,7 @@ class HTTPBackgroundLogger implements BackgroundLogger {
}

private async dumpDroppedEvents(
wrappedItems: LazyValue<BackgroundLogEvent | null>[],
wrappedItems: LazyValue<BackgroundLogEvent>[],
) {
const publishPayloadsDir = [
this.allPublishPayloadsDir,
Expand All @@ -3982,7 +3998,9 @@ class HTTPBackgroundLogger implements BackgroundLogger {
await this.unwrapLazyValues(wrappedItems);

const dataStr = constructLogs3Data(
allItems.map((x) => stringifyWithOverflowMeta(x)),
allItems.flatMap((group) =>
group.map((x) => stringifyWithOverflowMeta(x)),
),
);
const attachmentStr = JSON.stringify(
allAttachments.map((a) => a.debugInfo()),
Expand Down Expand Up @@ -7470,6 +7488,22 @@ function extractAttachments(
}
}

function collectAttachmentReferenceKeys(value: unknown, keys: Set<string>) {
if (!value || typeof value !== "object") return;
if (Array.isArray(value)) {
value.forEach((item) => collectAttachmentReferenceKeys(item, keys));
return;
}
const record = value as Record<string, unknown>;
if (record.type === BRAINTRUST_ATTACHMENT && typeof record.key === "string") {
keys.add(record.key);
return;
}
Object.values(record).forEach((item) =>
collectAttachmentReferenceKeys(item, keys),
);
}

/**
* Recursively hydrates any `AttachmentReference` into `Attachment` by modifying
* the input in-place.
Expand Down Expand Up @@ -8536,8 +8570,8 @@ export class SpanImpl implements Span {
}).objectIdFields(),
};
// Customize inside the memoized lazy value, before attachment processing,
// merging, and masking. Retries reuse the customized record or drop result.
return customizeSpanExport(record) as BackgroundLogEvent | null;
// merging, and masking. Retries reuse the customized or stripped record.
return customizeSpanExport(record) as BackgroundLogEvent;
};
this._state.bgLogger().log([new LazyValue(computeRecord)]);
}
Expand Down
33 changes: 30 additions & 3 deletions js/src/masking.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -547,7 +547,7 @@ describe("masking functionality", () => {
]);
});

test("dropped customizer records never reach masking or merge into successful records", async () => {
test("stripped customizer records bypass masking and remain independent of successful records", async () => {
vi.spyOn(console, "error").mockImplementation(() => {});
configureInstrumentation({
spanCustomizers: [
Expand All @@ -559,22 +559,49 @@ describe("masking functionality", () => {
},
],
});
const mask = vi.fn((data: unknown) => (data === "safe" ? "masked" : data));
const mask = vi.fn((data: unknown) => {
if (data && typeof data === "object" && "customizer_error" in data) {
return { injected: "must not replace SDK diagnostics" };
}
if (data && typeof data === "object" && "start" in data) {
return { start: 999, end: 999 };
}
return data === "safe" ? "masked" : data;
});
setMaskingFunction(mask);
const span = initLogger({
projectName: "test",
projectId: "test-project-id",
}).startSpan({ name: "manual" });
span.log({ output: "private", metadata: { secret: "private" } });
span.log({
output: "private",
metadata: { secret: "private" },
metrics: { start: 10, end: 20, tokens: 99 },
});
span.log({ output: "safe" });
span.end();

const events = await memoryLogger.drain();
expect(events).toEqual([
expect.objectContaining({
id: span.id,
span_attributes: expect.anything(),
}),
{
id: span.id,
span_id: span.spanId,
root_span_id: span.rootSpanId,
project_id: "test-project-id",
log_id: "g",
_is_merge: true,
context: { customizer_error: true },
metrics: { start: 10, end: 20 },
},
expect.objectContaining({ id: span.id, output: "masked" }),
]);
expect(JSON.stringify(events)).not.toContain("private");
expect(JSON.stringify(mask.mock.calls)).not.toContain("private");
expect(JSON.stringify(mask.mock.calls)).not.toContain("customizer_error");
});

test.each(["manual", "instrumented"])(
Expand Down
Loading
Loading