Skip to content

Commit 328d262

Browse files
authored
fix(logs): harden log schemas against API response format variations (#361)
Fixes CLI-BH The trace-logs endpoint (`/organizations/{org}/trace-logs/`) can return numeric fields as strings or omit optional fields, causing Zod validation failures in `apiRequestToRegion()`. ## Root Cause `TraceLogSchema` used strict `z.number()` for fields the API may return as strings or omit: - `timestamp_precise` — nanosecond timestamps (~1.7e18) exceed `Number.MAX_SAFE_INTEGER`, so the API may serialize them as strings - `project.id` — some responses return numeric IDs as strings - `severity_number` — may be absent from certain log entries ## Changes - **Schema hardening** (`src/types/sentry.ts`): Use `z.coerce.number()` on `timestamp_precise` (all 3 log schemas), `project.id`, and `severity_number`. Make `severity_number` and `timestamp_precise` optional on `TraceLogSchema`. - **Follow-mode fallbacks** (`src/commands/log/list.ts`): Handle optional `timestamp_precise` with `?? lastTimestamp` / `?? 0` in dedup filtering. - **Diagnostics** (`src/lib/api-client.ts`): Attach structured Zod validation issues to Sentry context so future schema failures include field-level details. - **Tests**: Unit tests for string coercion and missing optional fields. Property-based tests for schema coercion invariants.
1 parent a909191 commit 328d262

File tree

7 files changed

+347
-37
lines changed

7 files changed

+347
-37
lines changed

AGENTS.md

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -631,6 +631,9 @@ mock.module("./some-module", () => ({
631631
<!-- lore:019cb8ea-c6f0-75d8-bda7-e32b4e217f92 -->
632632
* **CLI telemetry DSN is public write-onlysafe to embed in install script**: The CLI's Sentry DSN (\`SENTRY\_CLI\_DSN\` in \`src/lib/constants.ts\`) is a public write-only ingest key already baked into every binary. Safe to hardcode in install scripts. Opt-out: \`SENTRY\_CLI\_NO\_TELEMETRY=1\`.
633633

634+
<!-- lore:019cbeba-e4d3-748c-ad50-fe3c3d5c0a0d -->
635+
* **Auth token env var override pattern: SENTRY\_AUTH\_TOKEN > SENTRY\_TOKEN > SQLite**: Authentication in \`src/lib/db/auth.ts\` follows layered precedence: \`SENTRY\_AUTH\_TOKEN\` env var > \`SENTRY\_TOKEN\` env var > SQLite-stored OAuth token. \`getEnvToken()\` reads env vars with \`.trim()\` (empty/whitespace = unset). \`AuthSource\` type tracks provenance: \`"env:SENTRY\_AUTH\_TOKEN"\` | \`"env:SENTRY\_TOKEN"\` | \`"oauth"\`. \`ENV\_SOURCE\_PREFIX = "env:"\` constant is used for parsing source strings (use \`.length\` not hardcoded 4). \`getActiveEnvVarName()\` is the shared helper for commands needing the env var name — calls \`getEnvToken()\` directly (no DB fallback). Env tokens bypass all refresh/expiry logic. \`isEnvTokenActive()\` is the guard for auth commands. Logout must NOT clear stored auth when env token active — just inform user to unset the env var. \`getEnvToken\`/\`isEnvTokenActive\` stay in \`db/auth.ts\` despite not touching DB, because they're tightly coupled with \`getAuthToken\`/\`getAuthConfig\`/\`refreshToken\`.
636+
634637
<!-- lore:019c978a-18b5-7a0d-a55f-b72f7789bdac -->
635638
* **cli.sentry.dev is served from gh-pages branch via GitHub Pages**: \`cli.sentry.dev\` is served from gh-pages branch via GitHub Pages. Craft's gh-pages target runs \`git rm -r -f .\` before extracting docs — persist extra files via \`postReleaseCommand\` in \`.craft.yml\`. Install script supports \`--channel nightly\`, downloading from the \`nightly\` release tag directly. version.json is only used by upgrade/version-check flow.
636639

src/commands/log/list.ts

Lines changed: 61 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -90,8 +90,9 @@ function parseFollow(value: string): number {
9090
*/
9191
type LogLike = {
9292
timestamp: string;
93-
/** Nanosecond-precision timestamp used for dedup in follow mode */
94-
timestamp_precise: number;
93+
/** Nanosecond-precision timestamp used for dedup in follow mode.
94+
* Optional because TraceLog may omit it when the API response doesn't include it. */
95+
timestamp_precise?: number;
9596
severity?: string | null;
9697
message?: string | null;
9798
trace?: string | null;
@@ -194,6 +195,11 @@ type FollowConfig<T extends LogLike> = {
194195
fetch: (statsPeriod: string, afterTimestamp?: number) => Promise<T[]>;
195196
/** Extract only the genuinely new entries from a poll response */
196197
extractNew: (logs: T[], lastTimestamp: number) => T[];
198+
/**
199+
* Called with the initial batch of logs before polling begins.
200+
* Use this to seed dedup state (e.g., tracking seen log IDs).
201+
*/
202+
onInitialLogs?: (logs: T[]) => void;
197203
};
198204

199205
/**
@@ -252,23 +258,38 @@ function executeFollowMode<T extends LogLike>(
252258
pendingTimer = setTimeout(poll, pollIntervalMs);
253259
}
254260

255-
function writeNewLogs(newLogs: T[]) {
256-
const newestLog = newLogs[0];
257-
if (newestLog) {
258-
if (!(flags.json || headerPrinted)) {
259-
stdout.write(table ? table.header() : formatLogsHeader());
260-
headerPrinted = true;
261+
/** Find the highest timestamp_precise in a batch, or undefined if none have it. */
262+
function maxTimestamp(logs: T[]): number | undefined {
263+
let max: number | undefined;
264+
for (const l of logs) {
265+
if (l.timestamp_precise !== undefined) {
266+
max =
267+
max === undefined
268+
? l.timestamp_precise
269+
: Math.max(max, l.timestamp_precise);
261270
}
262-
const chronological = [...newLogs].reverse();
263-
writeLogs({
264-
stdout,
265-
logs: chronological,
266-
asJson: flags.json,
267-
table,
268-
includeTrace: config.includeTrace,
269-
});
270-
lastTimestamp = newestLog.timestamp_precise;
271271
}
272+
return max;
273+
}
274+
275+
function writeNewLogs(newLogs: T[]) {
276+
if (newLogs.length === 0) {
277+
return;
278+
}
279+
280+
if (!(flags.json || headerPrinted)) {
281+
stdout.write(table ? table.header() : formatLogsHeader());
282+
headerPrinted = true;
283+
}
284+
const chronological = [...newLogs].reverse();
285+
writeLogs({
286+
stdout,
287+
logs: chronological,
288+
asJson: flags.json,
289+
table,
290+
includeTrace: config.includeTrace,
291+
});
292+
lastTimestamp = maxTimestamp(newLogs) ?? lastTimestamp;
272293
}
273294

274295
async function poll() {
@@ -311,9 +332,8 @@ function executeFollowMode<T extends LogLike>(
311332
table,
312333
includeTrace: config.includeTrace,
313334
});
314-
if (initialLogs[0]) {
315-
lastTimestamp = initialLogs[0].timestamp_precise;
316-
}
335+
lastTimestamp = maxTimestamp(initialLogs) ?? lastTimestamp;
336+
config.onInitialLogs?.(initialLogs);
317337
scheduleNextPoll();
318338
})
319339
.catch((error: unknown) => {
@@ -451,6 +471,9 @@ export const listCommand = buildListCommand("log", {
451471

452472
if (flags.follow) {
453473
const traceId = flags.trace;
474+
// Track IDs of logs seen without timestamp_precise so they are
475+
// shown once but not duplicated on subsequent polls.
476+
const seenWithoutTs = new Set<string>();
454477
await executeFollowMode({
455478
stdout,
456479
stderr,
@@ -464,7 +487,24 @@ export const listCommand = buildListCommand("log", {
464487
statsPeriod,
465488
}),
466489
extractNew: (logs, lastTs) =>
467-
logs.filter((l) => l.timestamp_precise > lastTs),
490+
logs.filter((l) => {
491+
if (l.timestamp_precise !== undefined) {
492+
return l.timestamp_precise > lastTs;
493+
}
494+
// No precise timestamp — deduplicate by id
495+
if (seenWithoutTs.has(l.id)) {
496+
return false;
497+
}
498+
seenWithoutTs.add(l.id);
499+
return true;
500+
}),
501+
onInitialLogs: (logs) => {
502+
for (const l of logs) {
503+
if (l.timestamp_precise === undefined) {
504+
seenWithoutTs.add(l.id);
505+
}
506+
}
507+
},
468508
});
469509
} else {
470510
await executeTraceSingleFetch(stdout, org, flags.trace, flags);

src/lib/api-client.ts

Lines changed: 8 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -359,9 +359,14 @@ export async function apiRequestToRegion<T>(
359359
if (schema) {
360360
const result = schema.safeParse(data);
361361
if (!result.success) {
362-
// Treat schema validation failures as API errors so they surface cleanly
363-
// through the central error handler rather than showing a raw ZodError
364-
// stack trace. This guards against unexpected API response format changes.
362+
// Attach structured Zod issues to the Sentry event so we can diagnose
363+
// exactly which field(s) failed validation — the ApiError.detail string
364+
// alone may not be visible in the Sentry issue overview.
365+
Sentry.setContext("zod_validation", {
366+
endpoint,
367+
status: response.status,
368+
issues: result.error.issues.slice(0, 10),
369+
});
365370
throw new ApiError(
366371
`Unexpected response format from ${endpoint}`,
367372
response.status,

src/types/sentry.ts

Lines changed: 20 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -480,8 +480,10 @@ export const SentryLogSchema = z
480480
"sentry.item_id": z.string(),
481481
/** ISO timestamp of the log entry */
482482
timestamp: z.string(),
483-
/** Nanosecond-precision timestamp for accurate ordering and filtering */
484-
timestamp_precise: z.number(),
483+
/** Nanosecond-precision timestamp for accurate ordering and filtering.
484+
* Coerced from string because the API may return large integers as strings
485+
* to avoid precision loss beyond Number.MAX_SAFE_INTEGER. */
486+
timestamp_precise: z.coerce.number(),
485487
/** Log message content */
486488
message: z.string().nullable().optional(),
487489
/** Log severity level (error, warning, info, debug, etc.) */
@@ -516,8 +518,10 @@ export const DetailedSentryLogSchema = z
516518
"sentry.item_id": z.string(),
517519
/** ISO timestamp of the log entry */
518520
timestamp: z.string(),
519-
/** Nanosecond-precision timestamp for accurate ordering */
520-
timestamp_precise: z.number(),
521+
/** Nanosecond-precision timestamp for accurate ordering.
522+
* Coerced from string because the API may return large integers as strings
523+
* to avoid precision loss beyond Number.MAX_SAFE_INTEGER. */
524+
timestamp_precise: z.coerce.number(),
521525
/** Log message content */
522526
message: z.string().nullable().optional(),
523527
/** Log severity level (error, warning, info, debug, etc.) */
@@ -584,18 +588,24 @@ export const TraceLogSchema = z
584588
.object({
585589
/** Unique identifier for this log entry */
586590
id: z.string(),
587-
/** Numeric ID of the project this log belongs to */
588-
"project.id": z.number(),
591+
/** Numeric ID of the project this log belongs to.
592+
* Coerced from string because some API responses return numeric IDs as strings. */
593+
"project.id": z.coerce.number(),
589594
/** The 32-character hex trace ID this log is associated with */
590595
trace: z.string(),
591-
/** Numeric OTel severity level (e.g., 9 = INFO, 13 = WARN, 17 = ERROR) */
592-
severity_number: z.number(),
596+
/** Numeric OTel severity level (e.g., 9 = INFO, 13 = WARN, 17 = ERROR).
597+
* Optional because not all log entries include this field.
598+
* Coerced from string for resilience against API format variations. */
599+
severity_number: z.coerce.number().optional(),
593600
/** Severity label (e.g., "info", "warn", "error") */
594601
severity: z.string(),
595602
/** ISO 8601 timestamp */
596603
timestamp: z.string(),
597-
/** High-precision timestamp in nanoseconds */
598-
timestamp_precise: z.number(),
604+
/** High-precision timestamp in nanoseconds.
605+
* Optional because some API responses may omit it.
606+
* Coerced from string because nanosecond timestamps (≈1.7e18 in 2026)
607+
* exceed Number.MAX_SAFE_INTEGER and APIs may return them as strings. */
608+
timestamp_precise: z.coerce.number().optional(),
599609
/** Log message content */
600610
message: z.string().nullable().optional(),
601611
})

test/commands/log/list.test.ts

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -784,7 +784,8 @@ describe("listCommand.func — follow mode (standard)", () => {
784784
});
785785

786786
test("passes afterTimestamp to poll calls", async () => {
787-
// sampleLogs[0] has the highest timestamp_precise (newest-first from API)
787+
// maxTimestamp scans the entire batch for the highest timestamp_precise
788+
const maxTs = Math.max(...sampleLogs.map((l) => l.timestamp_precise));
788789
listLogsSpy.mockResolvedValueOnce(sampleLogs).mockResolvedValueOnce([]);
789790
resolveOrgProjectSpy.mockResolvedValue({ org: ORG, project: PROJECT });
790791

@@ -797,10 +798,10 @@ describe("listCommand.func — follow mode (standard)", () => {
797798
sigint.trigger();
798799
await promise;
799800

800-
// Poll call (index 1) should include afterTimestamp from first log
801+
// Poll call (index 1) should include afterTimestamp from max in batch
801802
const pollCall = listLogsSpy.mock.calls[1];
802803
expect(pollCall).toBeDefined();
803-
expect(pollCall[2].afterTimestamp).toBe(sampleLogs[0].timestamp_precise);
804+
expect(pollCall[2].afterTimestamp).toBe(maxTs);
804805
expect(pollCall[2].statsPeriod).toBe("10m");
805806
});
806807

test/lib/api-client.test.ts

Lines changed: 75 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1574,4 +1574,79 @@ describe("listTraceLogs", () => {
15741574
const url = new URL(capturedUrl);
15751575
expect(url.searchParams.get("statsPeriod")).toBe("14d");
15761576
});
1577+
1578+
test("coerces string numeric fields to numbers (API resilience)", async () => {
1579+
const stringFieldsData = {
1580+
data: [
1581+
{
1582+
id: "log001",
1583+
"project.id": "123",
1584+
trace: "aaaa1111bbbb2222cccc3333dddd4444",
1585+
severity_number: "9",
1586+
severity: "info",
1587+
timestamp: "2025-01-30T14:32:15+00:00",
1588+
timestamp_precise: "1738247535000000000",
1589+
message: "Request received",
1590+
},
1591+
],
1592+
meta: { fields: { id: "string" } },
1593+
};
1594+
1595+
globalThis.fetch = async (input: RequestInfo | URL, init?: RequestInit) => {
1596+
const req = new Request(input, init);
1597+
if (req.url.includes("/trace-logs/")) {
1598+
return new Response(JSON.stringify(stringFieldsData), {
1599+
status: 200,
1600+
headers: { "Content-Type": "application/json" },
1601+
});
1602+
}
1603+
return new Response(JSON.stringify({}), { status: 200 });
1604+
};
1605+
1606+
const result = await listTraceLogs(
1607+
"my-org",
1608+
"aaaa1111bbbb2222cccc3333dddd4444"
1609+
);
1610+
expect(result).toHaveLength(1);
1611+
expect(typeof result[0]["project.id"]).toBe("number");
1612+
expect(result[0]["project.id"]).toBe(123);
1613+
expect(typeof result[0].severity_number).toBe("number");
1614+
expect(result[0].severity_number).toBe(9);
1615+
expect(typeof result[0].timestamp_precise).toBe("number");
1616+
});
1617+
1618+
test("accepts responses with missing optional fields", async () => {
1619+
const minimalData = {
1620+
data: [
1621+
{
1622+
id: "log001",
1623+
"project.id": 123,
1624+
trace: "aaaa1111bbbb2222cccc3333dddd4444",
1625+
severity: "info",
1626+
timestamp: "2025-01-30T14:32:15+00:00",
1627+
message: "Test",
1628+
},
1629+
],
1630+
};
1631+
1632+
globalThis.fetch = async (input: RequestInfo | URL, init?: RequestInit) => {
1633+
const req = new Request(input, init);
1634+
if (req.url.includes("/trace-logs/")) {
1635+
return new Response(JSON.stringify(minimalData), {
1636+
status: 200,
1637+
headers: { "Content-Type": "application/json" },
1638+
});
1639+
}
1640+
return new Response(JSON.stringify({}), { status: 200 });
1641+
};
1642+
1643+
const result = await listTraceLogs(
1644+
"my-org",
1645+
"aaaa1111bbbb2222cccc3333dddd4444"
1646+
);
1647+
expect(result).toHaveLength(1);
1648+
expect(result[0].severity_number).toBeUndefined();
1649+
expect(result[0].timestamp_precise).toBeUndefined();
1650+
expect(result[0].severity).toBe("info");
1651+
});
15771652
});

0 commit comments

Comments
 (0)