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
1 change: 1 addition & 0 deletions .changeset/v1.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
6 changes: 4 additions & 2 deletions AGENTS.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
8 changes: 8 additions & 0 deletions CONTEXT.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
4 changes: 2 additions & 2 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
7 changes: 5 additions & 2 deletions src/__tests__/Buffers.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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',
Expand All @@ -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()',
Expand Down Expand Up @@ -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([
Expand Down
58 changes: 58 additions & 0 deletions src/__tests__/Details.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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]);
});
});
7 changes: 5 additions & 2 deletions src/engine/issues.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
}

Expand Down
53 changes: 53 additions & 0 deletions src/engine/throws.ts
Original file line number Diff line number Diff line change
@@ -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<number, boolean> {
const { type, count } = store;
const throws = store.rowsOfType(THROWN);
const out = new Map<number, boolean>();
// 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;
}
28 changes: 23 additions & 5 deletions src/views/details.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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: {
Expand All @@ -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. */
Expand All @@ -67,8 +79,11 @@ export type DetailsOf<T extends EventType> = T extends keyof EventDetails ? Even
export type AnyDetails = EventDetails[keyof EventDetails];

type Read<T> = (f: Fields) => T;
/** Reads a line's details; `explain` gives a query's explain line, or null when it has none. */
type Reader<T> = (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<T> = (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 } {
Expand Down Expand Up @@ -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);
}
9 changes: 5 additions & 4 deletions src/views/events.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down Expand Up @@ -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);
}

Expand Down
11 changes: 9 additions & 2 deletions src/views/lines.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand All @@ -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<number, boolean> | 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);
}

Expand Down Expand Up @@ -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),
Expand All @@ -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,
);
}

Expand Down
Loading