From bea7ec587b2bf2f5bb22b4ccece810ccde729ae0 Mon Sep 17 00:00:00 2001 From: Luke Cotter <4013877+lukecotter@users.noreply.github.com> Date: Fri, 9 Oct 2026 18:17:13 +0100 Subject: [PATCH] feat: tell if each thrown exception was caught Add `isCaught` to the details of each `EXCEPTION_THROWN` event. It is the parser's reading of the row after the throw; the log does not state it. A `FATAL_ERROR` gives false, any other row gives true, so a `finally` block that logs before a `FATAL_ERROR` reads true. Throws with only exit lines between them share one answer, so a throw that a catch block wraps and throws again is false too. The log end, a limit block (including `TESTING_LIMITS`) or dropped lines give null. engine/throws.ts reads the outcome of every decided throw in one pass, on the first read, and EventLines holds the result for its log. The scan does not change. A max-size issue that moves to a closed frame now keeps where the dropped part starts, so a throw before a max-size cut reads null. Refs #123 --- .changeset/v1.md | 1 + AGENTS.md | 6 ++-- CONTEXT.md | 8 +++++ README.md | 4 +-- src/__tests__/Buffers.test.ts | 7 +++-- src/__tests__/Details.test.ts | 58 +++++++++++++++++++++++++++++++++++ src/engine/issues.ts | 7 +++-- src/engine/throws.ts | 53 ++++++++++++++++++++++++++++++++ src/views/details.ts | 28 ++++++++++++++--- src/views/events.ts | 9 +++--- src/views/lines.ts | 11 +++++-- 11 files changed, 173 insertions(+), 19 deletions(-) create mode 100644 src/engine/throws.ts diff --git a/.changeset/v1.md b/.changeset/v1.md index 31b8e86..9eeded7 100644 --- a/.changeset/v1.md +++ b/.changeset/v1.md @@ -10,6 +10,7 @@ How it works now, and what breaks: - **Async.** `const log = await parse(text)`. Takes a string, bytes, `Blob`, `Response`, stream or async iterable. Runs in 5 ms slices; `signal` cancels, `onProgress` reports. Optional `worker` option, and `toBuffers`/`fromBuffers` to move a log between threads. - **Views, not classes.** Event classes and `ApexLogParser` are gone, so no `instanceof`. Use `event.type`, or `event.kind` for a group. `ofType('SOQL_EXECUTE_BEGIN')` finds events and types `details` (was `limitUsage`). `ApexLog` is a type, not an event. +- **Caught throws.** `details.isCaught` on `EXCEPTION_THROWN`: `false` if a `FATAL_ERROR` follows, `true` if another row does, `null` if the log cannot tell. - **Frames and leaves.** `isParent` is now `isFrame`. A leaf has no children. Exit lines (`METHOD_EXIT`) are not events: they set `endTimestamp` and `duration` on their frame. - **Ids.** `eventIndex` is now `id`: from 1, valid for one parse. `log.event(id)`, `log.events`. `log.columns` gives times and tree links as typed arrays. - **Times.** `timestamp` → `startTimestamp`, `exitStamp` → `endTimestamp`. A leaf ends where it starts. diff --git a/AGENTS.md b/AGENTS.md index 8d40dd5..ed04af4 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -55,8 +55,10 @@ execution timings, governor limits, and SOQL/DML/SOSL counts. Zero runtime depen log. `views/lines.ts` reads an event's text, raw line, fields from the source when a caller asks, through the catalog's rules; the flow interviews name, which needs the tree, is the one rule it holds itself. `views/details.ts` reads the values a line states beyond - its text, as `aggregations` or a limit usage, one reader per type; `EventDetails` lists them, - and `ofType` types each event's `details`. `views/log.ts` reads row 0 as `ApexLog`, the root, and makes each figure that needs work + its text, as `aggregations` or a limit usage, and the values the rows after it give, as a + throw's `isCaught`, one reader per type; `EventDetails` lists them, + and `ofType` types each event's `details`. `engine/throws.ts` reads each throw's outcome from + the rows after it, in one pass on the first `isCaught` read. `views/log.ts` reads row 0 as `ApexLog`, the root, and makes each figure that needs work on first read. A merged package run can end after the leaves that follow it, so `at()` searches frames only. - `src/__tests__/` — vitest suites. `helpers.ts` holds shared fixtures. diff --git a/CONTEXT.md b/CONTEXT.md index d7c2998..3f1a389 100644 --- a/CONTEXT.md +++ b/CONTEXT.md @@ -50,6 +50,14 @@ frame's exit details. The facts a folded exit line stated, such as the row count of `SOQL_EXECUTE_END`. Null when the frame never closed. +**Details**: +The values an event's line states beyond its text, such as a query's plan, or that the parser reads +from the rows after it, such as whether a throw was caught. Not exit details. + +**Caught**: +The parser's reading of a throw from the row after it: a `FATAL_ERROR` follows, or another row +does. The log does not state it. + **Unterminated frame**: A frame that the log does not close, because the log ends or the platform dropped its exit line. _Avoid_: truncated event (truncation is a different thing, see below) diff --git a/README.md b/README.md index 9947ff2..ca785a2 100644 --- a/README.md +++ b/README.md @@ -21,8 +21,8 @@ VS Code extension and its [MCP server](https://github.com/certinia/debug-log-ana iterable. - **Node and browser builds**, with one API. An optional worker moves the parse off the main thread. -- **Every documented event type**, each with its kind of work (`kind`), its debug level and the - values its line states (`details`). +- **Every documented event type**, each with its kind of work (`kind`), its debug level and its + extra values (`details`), such as a query's plan or whether a throw was caught. - **An event tree** where each entry is matched to its exit, with self and total times in nanoseconds. - **Counts up the tree**: SOQL, DML and SOSL statements and rows, exceptions and heap. diff --git a/src/__tests__/Buffers.test.ts b/src/__tests__/Buffers.test.ts index 433560b..c9d3ec6 100644 --- a/src/__tests__/Buffers.test.ts +++ b/src/__tests__/Buffers.test.ts @@ -20,8 +20,9 @@ const LIMITS = [ '09:00:00.0 (900)|CUMULATIVE_LIMIT_USAGE_END', ]; -// Every part of a build: the header, namespaces, counts, heap, details, a flow running total, a -// flow error, limits, a skipped block, a frame left open and a line the parser cannot read. +// Every part of a build: the header, namespaces, counts, heap, details, a caught throw, a flow +// running total, a flow error, limits, a skipped block, a frame left open and a line the parser +// cannot read. const LOG = [ '64.0 APEX_CODE,FINE;APEX_PROFILING,INFO;CALLOUT,INFO;DB,INFO;SYSTEM,DEBUG;WORKFLOW,INFO', '09:15:30.25 (1)|USER_INFO|[EXTERNAL]|005000000000AAA|user@example.com|(GMT-08:00) Pacific Standard Time (America/Los_Angeles)|GMT-08:00', @@ -33,6 +34,7 @@ const LOG = [ '09:00:00.0 (55)|SOQL_EXECUTE_EXPLAIN|[2]|TableScan on MyObject__c : [], cardinality: 1, sobjectCardinality: 1, relativeCost 1.3', '09:00:00.0 (60)|SOQL_EXECUTE_END|[2]|Rows:2', '09:00:00.0 (70)|HEAP_ALLOCATE|[3]|Bytes:64', + '09:00:00.0 (75)|EXCEPTION_THROWN|[3]|System.NullPointerException: Attempt to de-reference a null object', '09:00:00.0 (80)|USER_DEBUG|[4]|DEBUG|café ☕', 'a line that continues the debug text', '09:00:00.0 (90)|METHOD_EXIT|[1]|01p000000000AAA|ns.MyClass.run()', @@ -115,6 +117,7 @@ it('the fixture states every part of a build', async () => { expect(log.ofType('FLOW_ELEMENT_BEGIN')[0]?.dmlCount.self).toBe(1); expect(log.ofType('SOQL_EXECUTE_EXPLAIN')[0]?.details).not.toBeNull(); expect(log.ofType('FLOW_ELEMENT_ERROR')[0]?.details.elementName).toBe('Update_Account'); + expect(log.ofType('EXCEPTION_THROWN')[0]?.details.isCaught).toBe(true); }); describe.each([ diff --git a/src/__tests__/Details.test.ts b/src/__tests__/Details.test.ts index 00640b0..1a0eed6 100644 --- a/src/__tests__/Details.test.ts +++ b/src/__tests__/Details.test.ts @@ -245,3 +245,61 @@ describe('limit and heap details', () => { expect(log.children[0]?.details).toBeNull(); }); }); + +describe('EXCEPTION_THROWN details', () => { + const THROW = + '09:18:22.6 (300)|EXCEPTION_THROWN|[5]|System.NullPointerException: Attempt to de-reference a null object'; + const FATAL = + '09:18:22.6 (500)|FATAL_ERROR|System.NullPointerException: Attempt to de-reference a null object'; + const DEBUG = '09:18:22.6 (600)|USER_DEBUG|[9]|DEBUG|went on'; + const ENTRY = '09:18:22.6 (200)|METHOD_ENTRY|[1]|01p000000000AAA|MyClass.run()'; + const EXIT = '09:18:22.6 (400)|METHOD_EXIT|[1]|01p000000000AAA|MyClass.run()'; + const SKIP = '*** Skipped 1,024 bytes of detailed log'; + const isCaught = (...lines: string[]) => + parse(inExecution(...lines)) + .ofType('EXCEPTION_THROWN') + .map((e) => e.details.isCaught); + + it('is caught when execution goes on after the throw', () => { + expect(isCaught(ENTRY, THROW, EXIT, DEBUG)).toEqual([true]); + }); + + it('is not caught when the frames exit and a fatal error follows', () => { + expect(isCaught(ENTRY, THROW, EXIT, FATAL)).toEqual([false]); + }); + + it('ends a run of throws at the first row that is not a throw or an exit', () => { + expect(isCaught(THROW, DEBUG, THROW, FATAL)).toEqual([true, false]); + }); + + it('gives a run of throws the answer of the row after the run', () => { + expect(isCaught(THROW, THROW, FATAL)).toEqual([false, false]); + expect(isCaught(THROW, EXIT, THROW, DEBUG)).toEqual([true, true]); + }); + + it('skips an exit line that closes no frame', () => { + expect(isCaught(THROW, EXIT, FATAL)).toEqual([false]); + }); + + it('is caught when the platform drops lines before the throw only', () => { + expect(isCaught(SKIP, THROW, DEBUG)).toEqual([true]); + }); + + it('reads each throw against the next part the platform dropped', () => { + expect(isCaught(THROW, SKIP, DEBUG, THROW, DEBUG)).toEqual([null, true]); + expect(isCaught(THROW, DEBUG, SKIP, THROW, DEBUG)).toEqual([true, true]); + }); + + it.each([ + ['the log ends after it', [THROW]], + ['the limit block follows it', [THROW, '09:18:22.6 (900)|CUMULATIVE_LIMIT_USAGE']], + ['a test limit block follows it', [THROW, '09:18:22.6 (900)|TESTING_LIMITS']], + ['the platform drops lines after it', [THROW, SKIP, DEBUG]], + [ + 'the log reaches its maximum size after it', + [ENTRY, THROW, '*** MAXIMUM DEBUG LOG SIZE REACHED ***', DEBUG], + ], + ])('is null when %s', (_name, lines) => { + expect(isCaught(...lines)).toEqual([null]); + }); +}); diff --git a/src/engine/issues.ts b/src/engine/issues.ts index 7c1d502..b880e9c 100644 --- a/src/engine/issues.ts +++ b/src/engine/issues.ts @@ -122,9 +122,12 @@ export class Issues { replace(startTime: number, id: number, text: IssueText): Issue | null { const key = `${text.type}:${text.summary}`; const at = this.list.findIndex((issue) => `${issue.type}:${issue.summary}` === key); - if (at > -1) this.list.splice(at, 1); + const [held] = at > -1 ? this.list.splice(at, 1) : []; this.keys.delete(key); - return this.add(startTime, id, text); + const issue = this.add(startTime, id, text); + // The cut is where the dropped part starts, not where the issue moves to. + if (issue && held) issue.after = held.after; + return issue; } } diff --git a/src/engine/throws.ts b/src/engine/throws.ts new file mode 100644 index 0000000..0509877 --- /dev/null +++ b/src/engine/throws.ts @@ -0,0 +1,53 @@ +/* + * Copyright (c) 2026 Certinia Inc. All rights reserved. + */ +import { idOfType } from '../catalog/catalog.js'; +import type { Store } from '../store/store.js'; +import type { Issues } from './issues.js'; +import { ISSUE_TYPE } from './issues.js'; +import { EXIT_LINE } from './tables.js'; + +const THROWN = idOfType('EXCEPTION_THROWN'); +const FATAL = idOfType('FATAL_ERROR'); +// The platform writes these once execution ends, so a throw before them can be caught or not. +const AFTER_EXECUTION = new Set( + ( + [ + 'CUMULATIVE_LIMIT_USAGE', + 'LIMIT_USAGE_FOR_NS', + 'TESTING_LIMITS', + 'CUMULATIVE_PROFILING_BEGIN', + ] as const + ).map(idOfType), +); + +/** + * Whether each throw was caught, by row id: false when a `FATAL_ERROR` follows it, true when any + * other row does. A throw the log cannot tell has no entry. A run of throws with only exit lines + * between takes the answer of the row after the run. One pass over the throws and those lines. + */ +export function throwOutcomes(store: Store, issues: Issues): Map { + const { type, count } = store; + const throws = store.rowsOfType(THROWN); + const out = new Map(); + // The first row after each part the platform dropped, in log order. + const cuts = issues.list + .filter((issue) => issue.type === ISSUE_TYPE.Skip) + .map((issue) => issue.after) + .sort((a, b) => a - b); + let cut = 0; + for (let i = 0; i < throws.length; ) { + // Each entry and each id below count is a row. + const first = throws[i]!; + let next = first + 1; + while (next < count && (EXIT_LINE[type[next]!] === 1 || type[next] === THROWN)) next++; + while (cut < cuts.length && cuts[cut]! <= first) cut++; + const after = next < count ? type[next]! : -1; + const known = + after >= 0 && !AFTER_EXECUTION.has(after) && !(cut < cuts.length && cuts[cut]! <= next); + for (; i < throws.length && throws[i]! < next; i++) { + if (known) out.set(throws[i]!, after !== FATAL); + } + } + return out; +} diff --git a/src/views/details.ts b/src/views/details.ts index f961554..26cac1f 100644 --- a/src/views/details.ts +++ b/src/views/details.ts @@ -30,8 +30,9 @@ export interface ExplainPlan { } /** - * The values each type's line states beyond its text, by type. A value is null when the line does - * not state it, or states it malformed; `field()` still gives the raw text. + * The values each type's line states beyond its text, or derives from the rows after it, by type. A + * value is null when the log does not state it, or states it malformed; `field()` still gives the + * raw text. */ export interface EventDetails { readonly SOQL_EXECUTE_BEGIN: { @@ -58,6 +59,17 @@ export interface EventDetails { readonly elementType: string | null; readonly elementName: string | null; }; + readonly EXCEPTION_THROWN: { + /** + * The parser's reading of the row after the throw; the log does not state it. False when a + * `FATAL_ERROR` follows, true when any other row does, so a `finally` block that logs before a + * `FATAL_ERROR` reads true. Throws with only exit lines between them share one answer, so a + * throw that a catch block wraps and throws again is false too. Null when the log cannot tell: + * it ends, a limit block starts, or it drops lines before the next event. A merged + * `ENTERING_MANAGED_PKG` has no row, so the code it ran is not seen. + */ + readonly isCaught: boolean | null; + }; } /** The details of an event of type `T`: null for a type that states none. */ @@ -67,8 +79,11 @@ export type DetailsOf = T extends keyof EventDetails ? Even export type AnyDetails = EventDetails[keyof EventDetails]; type Read = (f: Fields) => T; -/** Reads a line's details; `explain` gives a query's explain line, or null when it has none. */ -type Reader = (f: Fields, explain: () => Fields | null) => T; +/** + * Reads a line's details; `explain` gives a query's explain line, or null when it has none, and + * `isCaught` the reading of a throw. + */ +type Reader = (f: Fields, explain: () => Fields | null, isCaught: () => boolean | null) => T; /** Field `name`'s position in `typeId`'s line; throws at load for a name the entry does not list. */ function position(typeId: number, name: string): { at: number; last: boolean } { @@ -193,13 +208,16 @@ reader('FLOW_ELEMENT_ERROR', (t) => (f) => { return { elementType: split?.[1] || null, elementName: split?.[2] || null }; }); +reader('EXCEPTION_THROWN', () => (_f, _explain, isCaught) => ({ isCaught: isCaught() })); + /** The details `typeId`'s line states, or null for a type that has none. Frozen: views share them. */ export function eventDetails( typeId: number, f: () => Fields, explain: () => Fields | null, + isCaught: () => boolean | null, ): AnyDetails | null { const read = READERS[typeId]; - const details = read ? read(f(), explain) : null; + const details = read ? read(f(), explain, isCaught) : null; return details && Object.freeze(details); } diff --git a/src/views/events.ts b/src/views/events.ts index 13ad949..7500b63 100644 --- a/src/views/events.ts +++ b/src/views/events.ts @@ -79,8 +79,9 @@ interface EventBase extends Rollups { */ field(name: string): string | null; /** - * The values the line states beyond its text, parsed on first read, as `aggregations` or a limit - * usage: `EventDetails` lists them by type. Null for a type that states none. + * The values the line states beyond its text, or derives from the rows after it, parsed on first + * read, as `aggregations`, a limit usage or a throw's `isCaught`: `EventDetails` lists them by + * type. Null for a type that has none. */ readonly details: AnyDetails | null; } @@ -128,10 +129,10 @@ export class LogEvents { readonly lines: EventLines; private readonly views: (ApexEvent | undefined)[]; - constructor({ store, strings, source }: Built) { + constructor({ store, strings, source, issues }: Built) { this.store = store; this.strings = strings; - this.lines = new EventLines(store, source); + this.lines = new EventLines(store, source, issues); this.views = new Array(store.count); } diff --git a/src/views/lines.ts b/src/views/lines.ts index 4582c91..c154d3e 100644 --- a/src/views/lines.ts +++ b/src/views/lines.ts @@ -4,6 +4,8 @@ import { ByteFields } from '../bytes/cursor.js'; import type { Source } from '../bytes/source.js'; import { EVENT_TYPES, eventText, fieldPosition, idOfType } from '../catalog/catalog.js'; +import type { Issues } from '../engine/issues.js'; +import { throwOutcomes } from '../engine/throws.js'; import type { Store } from '../store/store.js'; import type { AnyDetails } from './details.js'; import { eventDetails } from './details.js'; @@ -18,10 +20,14 @@ const EXPLAIN = idOfType('SOQL_EXECUTE_EXPLAIN'); */ export class EventLines { private readonly store: Store; + private readonly issues: Issues; private readonly fields: ByteFields; + /** Whether each decided throw was caught, by row; made on the first read of one. */ + private outcomes: Map | null = null; - constructor(store: Store, source: Source) { + constructor(store: Store, source: Source, issues: Issues) { this.store = store; + this.issues = issues; this.fields = new ByteFields(source); } @@ -54,7 +60,7 @@ export class EventLines { return (last ? f.from(at, '|') : f.at(at)) || null; } - /** The values the row's line states beyond its text; null for a type with none. */ + /** The values the row's line states beyond its text, or the rows after it give; null for none. */ details(id: number): AnyDetails | null { return eventDetails( this.typeOf(id), @@ -64,6 +70,7 @@ export class EventLines { const plan = this.firstChildOf(id, EXPLAIN); return plan < 0 ? null : this.at(plan); }, + () => (this.outcomes ??= throwOutcomes(this.store, this.issues)).get(id) ?? null, ); }