Add stack trace to failing require statements inside functions

packages/cashscript/src/Errors.ts

@@ -1,5 +1,11 @@
-import { Artifact, RequireStatement, sourceMapToLocationData, Type } from '@cashscript/utils';
-import { ResolvedFrame, resolveInlineAttribution, rootFrame } from './debug-frame.js';
+import { Artifact, RequireStatement, Type } from '@cashscript/utils';
+import {
+  CallStackEntry,
+  ResolvedFrame,
+  getLocationDataForFrame,
+  resolveInlineAttribution,
+  rootFrame,
+} from './debug-frame.js';
 
 export class TypeError extends Error {
   constructor(actual: string, expected: Type) {
@@ -159,6 +165,7 @@ export class FailedRequireError extends FailedTransactionError {
     public bitauthUri: string,
     public libauthErrorMessage?: string,
     frame?: ResolvedFrame,
+    public callStack: CallStackEntry[] = [],
   ) {
     const resolvedFrame = frame ?? rootFrame(artifact);
 
@@ -175,9 +182,12 @@ export class FailedRequireError extends FailedTransactionError {
 
     // Compiler-injected guards (e.g. the tx.locktime guard) have no user-written source, so the
     // extracted statement is empty — the require message fully describes the failure on its own.
-    const fullMessage = statement.trim() ? `${headline}\nFailing statement: ${statement}` : headline;
+    const statementMessage = statement.trim() ? `${headline}\nFailing statement: ${statement}` : headline;
 
-    super(fullMessage, bitauthUri);
+    // A single-entry call stack adds nothing over the headline, so it is only shown for nested calls
+    const callStackMessage = callStack.length >= 2 ? `\n${formatCallStack(callStack)}` : '';
+
+    super(statementMessage + callStackMessage, bitauthUri);
   }
 }
 
@@ -189,28 +199,9 @@ const formatFrameContext = (frame: ResolvedFrame, contractName: string, lineNumb
   return `in contract ${contractName}.cash at line ${lineNumber}`;
 };
 
-const getLocationDataForFrame = (
-  frame: ResolvedFrame,
-  instructionPointer: number,
-): { lineNumber: number, statement: string } => {
-  const locationData = sourceMapToLocationData(frame.sourceMap);
-
-  // We subtract the frame's ip offset (the constructor-arg prefix for the root frame, 0 for helper
-  // frames) because those pushes are present in the evaluation (and thus the instruction pointer) but
-  // not in the source code (and thus the location data).
-  const modifiedInstructionPointer = instructionPointer - frame.ipOffset;
-
-  const { location } = locationData[modifiedInstructionPointer];
-
-  const failingLines = frame.source.split('\n').slice(location.start.line - 1, location.end.line);
-
-  // Slice off the start and end of the statement's start and end lines to only return the failing part
-  // Note that we first slice off the end, to avoid shifting the end column index
-  failingLines[failingLines.length - 1] = failingLines[failingLines.length - 1].slice(0, location.end.column);
-  failingLines[0] = failingLines[0].slice(location.start.column);
-
-  const statement = failingLines.join('\n');
-  const lineNumber = location.start.line;
-
-  return { statement, lineNumber };
-};
+const formatCallStack = (callStack: CallStackEntry[]): string => callStack
+  .map(({ functionName, sourceName, line, statement }) => {
+    const location = functionName ? `${functionName} (${sourceName}:${line})` : `${sourceName}:${line}`;
+    return `  at ${location} — ${statement}`;
+  })
+  .join('\n');

packages/cashscript/src/debug-frame.ts

@@ -1,5 +1,24 @@
-import { AuthenticationProgramStateCommon, binToHex, encodeAuthenticationInstructions } from '@bitauth/libauth';
-import { Artifact, DebugEntry, DebugFrame, LogEntry, RequireStatement, parseInlineRanges } from '@cashscript/utils';
+import {
+  AuthenticationInstruction,
+  AuthenticationProgramStackFrame,
+  AuthenticationProgramStateCommon,
+  binToHex,
+  encodeAuthenticationInstructions,
+  hexToBin,
+} from '@bitauth/libauth';
+import {
+  Artifact,
+  DebugEntry,
+  DebugFrame,
+  InlineRange,
+  LogEntry,
+  Op,
+  RequireStatement,
+  Script,
+  bytecodeToScript,
+  parseAndResolveInlineRanges,
+  sourceMapToLocationData,
+} from '@cashscript/utils';
 
 export interface ResolvedFrame {
   sourceMap: string;
@@ -12,6 +31,13 @@ export interface ResolvedFrame {
   functionName?: string;
 }
 
+export interface CallStackEntry {
+  functionName?: string; // absent for the contract's own code
+  sourceName: string;
+  line: number;
+  statement: string; // flattened to a single line for display
+}
+
 export const rootFrame = (artifact: Artifact): ResolvedFrame => ({
   sourceMap: artifact.debug?.sourceMap ?? '',
   source: artifact.source,
@@ -22,22 +48,22 @@ export const rootFrame = (artifact: Artifact): ResolvedFrame => ({
   inlineRanges: artifact.debug?.inlineRanges,
 });
 
-export const getActiveBytecode = (step: AuthenticationProgramStateCommon): string =>
-  binToHex(encodeAuthenticationInstructions(step.instructions));
+export const getActiveBytecode = (instructions: AuthenticationInstruction[]): string =>
+  binToHex(encodeAuthenticationInstructions(instructions));
 
 export const resolveFrame = (
   artifact: Artifact,
   step: AuthenticationProgramStateCommon,
-): ResolvedFrame => {
-  // Only defined frames (id present) execute as standalone VM functions; an inlined callable's
-  // frame documents a body that only ever runs spliced into another program
-  const frames = (artifact.debug?.functions ?? []).filter((candidate) => candidate.id !== undefined);
-  const activeBytecode = frames.length > 0 ? getActiveBytecode(step) : undefined;
-  const frame = frames.find((candidate) => candidate.bytecode === activeBytecode);
+): ResolvedFrame => resolveFrameByBytecode(artifact, getActiveBytecode(step.instructions));
 
-  if (!frame) return rootFrame(artifact);
+// Only defined frames (id present) execute as standalone VM programs; an inlined callable's
+// frame documents a body that only ever runs spliced into another program
+const resolveFrameByBytecode = (artifact: Artifact, activeBytecode: string): ResolvedFrame => {
+  const frame = (artifact.debug?.functions ?? [])
+    .filter((candidate) => candidate.id !== undefined)
+    .find((candidate) => candidate.bytecode === activeBytecode);
 
-  return resolveDebugFrame(artifact, frame);
+  return frame ? resolveDebugFrame(artifact, frame) : rootFrame(artifact);
 };
 
 const resolveDebugFrame = (artifact: Artifact, frame: DebugFrame): ResolvedFrame => ({
@@ -48,7 +74,7 @@ const resolveDebugFrame = (artifact: Artifact, frame: DebugFrame): ResolvedFrame
   requires: frame.requires,
   logs: frame.logs,
   inlineRanges: frame.inlineRanges,
-  functionName: frame.sourceFile ? frame.name : undefined,
+  functionName: frame.name,
 });
 
 export interface InlineAttribution {
@@ -62,20 +88,31 @@ export const resolveInlineAttribution = (
   entry: DebugEntry,
   kind: 'requires' | 'logs',
 ): InlineAttribution | undefined => {
-  const range = parseInlineRanges(containerFrame.inlineRanges ?? '')
-    .find((candidate) => entry.ip >= candidate.startIp && entry.ip <= candidate.endIp);
-  if (!range) return undefined;
+  const attributionStack = resolveInlineAttributionStack(artifact, containerFrame, entry, kind);
+  return attributionStack[0];
+};
 
-  const inlinedFrame = artifact.debug?.functions?.find((candidate) => candidate.name === range.frameName);
-  if (!inlinedFrame) return undefined;
+// The chain of inlined callables containing the entry, from the innermost to the outermost
+const resolveInlineAttributionStack = (
+  artifact: Artifact,
+  containerFrame: ResolvedFrame,
+  entry: DebugEntry,
+  kind: 'requires' | 'logs',
+): InlineAttribution[] => {
+  const range = parseAndResolveInlineRanges(containerFrame.inlineRanges, artifact.debug?.functions)
+    .find((candidate) => entry.ip >= candidate.startIp && entry.ip <= candidate.endIp);
+  if (!range) return [];
 
-  const frameEntry = findMatchingFrameEntry(containerFrame[kind], inlinedFrame[kind], range, entry);
-  if (!frameEntry) return undefined;
+  const frameEntry = findMatchingFrameEntry(containerFrame[kind], range.frame[kind], range, entry);
+  if (!frameEntry) return [];
 
-  const frame = resolveDebugFrame(artifact, inlinedFrame);
+  const frame = resolveDebugFrame(artifact, range.frame);
 
-  // The callable may itself contain deeper inlined callables: attribute to the innermost one
-  return resolveInlineAttribution(artifact, frame, frameEntry, kind) ?? { frame, entry: frameEntry };
+  // The callable may itself contain deeper inlined callables
+  return [
+    ...resolveInlineAttributionStack(artifact, frame, frameEntry, kind),
+    { frame, entry: frameEntry },
+  ];
 };
 
 // A log merged from an inlined callable is attributed to the callable's own source
@@ -107,3 +144,118 @@ const findMatchingFrameEntry = (
   if (position === -1) return undefined;
   return frameEntries[position];
 };
+
+export const buildCallStack = (
+  artifact: Artifact,
+  failingStep: AuthenticationProgramStateCommon,
+  failingFrame: ResolvedFrame,
+  requireStatement: RequireStatement,
+  failingInstructionPointer: number,
+): CallStackEntry[] => {
+  // These entries represent any called inlined functions at the top of the call stack. These are handled separately,
+  // because the failing debug step refers to the frameEntry below, so we manually need to handle "deeper" calls
+  const inlineEntries = resolveInlineAttributionStack(artifact, failingFrame, requireStatement, 'requires')
+    .map(({ frame, entry }) => toCallStackEntry(frame, entry.ip));
+
+  // This entry is the actual VM-level failing function
+  const frameEntry = toCallStackEntry(failingFrame, failingInstructionPointer);
+
+  // These entries are the rest of the callstack, so all the intermediate (defined & inlined) functions that call
+  // the VM-level failing function
+  const runtimeCallers = failingStep.controlStack
+    .filter(isAuthenticationProgramStackFrame)
+    .reverse()
+    .flatMap((controlFrame) => {
+      const callerBytecode = getActiveBytecode(controlFrame.instructions);
+      const callerFrame = resolveFrameByBytecode(artifact, callerBytecode);
+      // The control frame stores the ip to resume at, which is one past the OP_INVOKE call site
+      return expandRuntimeCaller(artifact, callerFrame, bytecodeToScript(hexToBin(callerBytecode)), controlFrame.ip - 1);
+    });
+
+  return [...inlineEntries, frameEntry, ...runtimeCallers];
+};
+
+const expandRuntimeCaller = (
+  artifact: Artifact,
+  frame: ResolvedFrame,
+  script: Script,
+  invokeIp: number,
+): CallStackEntry[] => [
+  ...resolveInlinedCallerHops(artifact, frame, script, invokeIp),
+  toCallStackEntry(frame, invokeIp),
+];
+
+// Every defined function already gets expanded in buildCallStack, so this function exists to make sure any inlined
+// callers also get added to the call stack
+const resolveInlinedCallerHops = (
+  artifact: Artifact,
+  frame: ResolvedFrame,
+  script: Script,
+  invokeIp: number,
+): CallStackEntry[] => {
+  const inlineRange = parseAndResolveInlineRanges(frame.inlineRanges, artifact.debug?.functions)
+    .find((candidate) => invokeIp >= candidate.startIp && invokeIp <= candidate.endIp);
+  if (!inlineRange) return [];
+
+  const frameScript = bytecodeToScript(hexToBin(inlineRange.frame.bytecode));
+  const frameLocalIp = findMatchingFrameInvokeIp(script, frameScript, inlineRange, invokeIp);
+  if (frameLocalIp === undefined) return [];
+
+  // The invoke is expanded again within the callable, since deeper inlined callables may wrap it
+  return expandRuntimeCaller(artifact, resolveDebugFrame(artifact, inlineRange.frame), frameScript, frameLocalIp);
+};
+
+// The container's n-th OP_INVOKE within the range corresponds to the n-th OP_INVOKE in the inlined
+// callable's own bytecode, matching by position gives the invoke's exact frame-local ip.
+const findMatchingFrameInvokeIp = (
+  containerScript: Script,
+  frameScript: Script,
+  range: InlineRange,
+  invokeIp: number,
+): number | undefined => {
+  const position = containerScript.slice(range.startIp, invokeIp).filter((op) => op === Op.OP_INVOKE).length;
+  const frameInvokeIps = frameScript.flatMap((op, ip) => (op === Op.OP_INVOKE ? [ip] : []));
+  return frameInvokeIps[position];
+};
+
+const isAuthenticationProgramStackFrame = (
+  item: AuthenticationProgramStackFrame | boolean | number,
+): item is AuthenticationProgramStackFrame => typeof item === 'object';
+
+const toCallStackEntry = (frame: ResolvedFrame, instructionPointer: number): CallStackEntry => {
+  const { lineNumber, statement } = getLocationDataForFrame(frame, instructionPointer);
+  const flattenedStatement = statement.split('\n').map((line) => line.trim()).join(' ');
+
+  return {
+    functionName: frame.functionName,
+    sourceName: frame.sourceName,
+    line: lineNumber,
+    statement: flattenedStatement,
+  };
+};
+
+export const getLocationDataForFrame = (
+  frame: ResolvedFrame,
+  instructionPointer: number,
+): { lineNumber: number, statement: string } => {
+  const locationData = sourceMapToLocationData(frame.sourceMap);
+
+  // We subtract the frame's ip offset (the constructor-arg prefix for the root frame, 0 for helper
+  // frames) because those pushes are present in the evaluation (and thus the instruction pointer) but
+  // not in the source code (and thus the location data).
+  const modifiedInstructionPointer = instructionPointer - frame.ipOffset;
+
+  const { location } = locationData[modifiedInstructionPointer];
+
+  const failingLines = frame.source.split('\n').slice(location.start.line - 1, location.end.line);
+
+  // Slice off the start and end of the statement's start and end lines to only return the failing part
+  // Note that we first slice off the end, to avoid shifting the end column index
+  failingLines[failingLines.length - 1] = failingLines[failingLines.length - 1].slice(0, location.end.column);
+  failingLines[0] = failingLines[0].slice(location.start.column);
+
+  const statement = failingLines.join('\n');
+  const lineNumber = location.start.line;
+
+  return { statement, lineNumber };
+};

packages/cashscript/src/debugging.ts

@@ -2,7 +2,7 @@ import { AuthenticationErrorCommon, AuthenticationInstruction, AuthenticationPro
 import { Artifact, LogData, LogEntry, Op, PrimitiveType, StackItem, asmToBytecode, bytecodeToAsm, decodeBool, decodeInt, decodeString } from '@cashscript/utils';
 import { findLastIndex, toRegExp } from './utils.js';
 import { FailedRequireError, FailedTransactionError, FailedTransactionEvaluationError } from './Errors.js';
-import { attributeLogEntry, getActiveBytecode, resolveFrame } from './debug-frame.js';
+import { attributeLogEntry, buildCallStack, getActiveBytecode, resolveFrame } from './debug-frame.js';
 import { getBitauthUri } from './libauth-template/LibauthTemplate.js';
 import { VmTarget } from './interfaces.js';
 
@@ -100,7 +100,7 @@ const debugSingleScenario = (
         if (logEntries.length === 0) return [];
 
         const reversedPriorDebugSteps = executedDebugSteps.slice(0, index + 1).reverse();
-        const frameBytecode = getActiveBytecode(debugStep);
+        const frameBytecode = getActiveBytecode(debugStep.instructions);
 
         return logEntries.map((logEntry) => {
           const decodedLogData = logEntry.data
@@ -148,9 +148,11 @@ const debugSingleScenario = (
     const requireStatement = frame.requires.find((statement) => statement.ip === requireStatementIp);
 
     if (requireStatement) {
+      const callStack = buildCallStack(artifact, lastExecutedDebugStep, frame, requireStatement, failingIp);
+
       // Note that we use failingIp here rather than requireStatementIp, see comment above
       throw new FailedRequireError(
-        artifact, failingIp, requireStatement, inputIndex, getBitauthUri(template), error, frame,
+        artifact, failingIp, requireStatement, inputIndex, getBitauthUri(template), error, frame, callStack,
       );
     }
 
@@ -188,8 +190,19 @@ const debugSingleScenario = (
     const requireStatement = frame.requires.find((message) => message.ip === finalExecutedVerifyIp);
 
     if (requireStatement) {
+      const callStack = buildCallStack(
+        artifact, lastExecutedDebugStep, frame, requireStatement, sourcemapInstructionPointer,
+      );
+
       throw new FailedRequireError(
-        artifact, sourcemapInstructionPointer, requireStatement, inputIndex, getBitauthUri(template), undefined, frame,
+        artifact,
+        sourcemapInstructionPointer,
+        requireStatement,
+        inputIndex,
+        getBitauthUri(template),
+        undefined,
+        frame,
+        callStack,
       );
     }
 
@@ -260,7 +273,7 @@ const decodeLogDataEntry = (
   if (typeof dataEntry === 'string') return dataEntry;
 
   const dataEntryDebugStep = reversedPriorDebugSteps.find(
-    (step) => step.ip === dataEntry.ip && getActiveBytecode(step) === frameBytecode,
+    (step) => step.ip === dataEntry.ip && getActiveBytecode(step.instructions) === frameBytecode,
   );
 
   if (!dataEntryDebugStep) {