Add SDK debugging support for user-defined functions

packages/cashc/src/ast/AST.ts

@@ -75,6 +75,10 @@ export class FunctionDefinitionNode extends Node implements Named {
   symbolTable?: SymbolTable;
   opRolls: Map<string, IdentifierNode> = new Map();
 
+  // Source provenance for debugging. Set on imported functions, left undefined for functions in the contract's own file.
+  sourceCode?: string;
+  sourceFile?: string;
+
   constructor(
     public kind: FunctionKind,
     public name: string,

packages/cashc/src/compiler.ts

@@ -99,6 +99,7 @@ export function compileString(code: string, compilerOptions: CompileOptions = {}
     logs: optimisationResult.logs,
     requires: optimisationResult.requires,
     ...(sourceTags ? { sourceTags } : {}),
+    ...(traversal.frames.length > 0 ? { functions: traversal.frames } : {}),
   };
 
   const fingerprint = computeBytecodeFingerprintWithConstructorArgs(optimisationResult.script, constructorParamLength);

packages/cashc/src/dependency-resolution.ts

@@ -36,7 +36,15 @@ function collectImports(
       if (visitedPaths.has(absolutePath)) return [];
       visitedPaths.add(absolutePath);
 
-      const importedAst = parseCode(readImportedFile(importNode, absolutePath), options.errorListener);
+      const importedSource = readImportedFile(importNode, absolutePath);
+      const importedAst = parseCode(importedSource, options.errorListener);
+
+      // Record source provenance so debug frames can attribute to the imported file
+      importedAst.functions.forEach((func) => {
+        func.sourceCode = importedSource;
+        func.sourceFile = path.basename(absolutePath);
+      });
+
       return [...collect(importedAst.imports, path.dirname(absolutePath)), ...importedAst.functions];
     });
 

packages/cashc/src/generation/GenerateTargetTraversal.ts

@@ -1,4 +1,4 @@
-import { hexToBin } from '@bitauth/libauth';
+import { binToHex, hexToBin } from '@bitauth/libauth';
 import {
   asmToScript,
   encodeBool,
@@ -13,6 +13,7 @@ import {
   optimiseBytecode,
   generateSourceMap,
   FullLocationData,
+  DebugFrame,
   LogEntry,
   RequireStatement,
   PositionHint,
@@ -77,6 +78,7 @@ export default class GenerateTargetTraversal extends AstTraversal {
   consoleLogs: LogEntry[] = [];
   requires: RequireStatement[] = [];
   sourceTags: SourceTagEntry[] = [];
+  frames: DebugFrame[] = [];
   finalStackUsage: Record<string, StackItem> = {};
 
   private scopeDepth = 0;
@@ -183,7 +185,20 @@ export default class GenerateTargetTraversal extends AstTraversal {
       0,
     );
 
-    return scriptToBytecode(optimised.script);
+    const bodyBytecode = scriptToBytecode(optimised.script);
+
+    this.frames.push({
+      name: node.name,
+      inputs: node.parameters.map((parameter) => ({ name: parameter.name, type: parameter.type.toString() })),
+      bytecode: binToHex(bodyBytecode),
+      sourceMap: generateSourceMap(optimised.locationData),
+      logs: optimised.logs,
+      requires: optimised.requires,
+      ...(node.sourceCode !== undefined ? { source: node.sourceCode } : {}),
+      ...(node.sourceFile !== undefined ? { sourceFile: node.sourceFile } : {}),
+    });
+
+    return bodyBytecode;
   }
 
   cleanGlobalFunctionStack(node: FunctionDefinitionNode): void {

packages/cashc/test/generation/fixtures.ts

@@ -1427,6 +1427,9 @@ export const fixtures: Fixture[] = [
           { ip: 7, line: 7 },
         ],
         sourceMap: '1::3:1;;::::1;7:16:7:25;;:29::30:0;:8::32:1',
+        functions: [
+          { name: 'double', inputs: [{ name: 'a', type: 'int' }], bytecode: '5295', sourceMap: '2:15:2:16;:11:::1', logs: [], requires: [] },
+        ],
       },
       source: fs.readFileSync(new URL('../valid-contract-files/global_function_simple.cash', import.meta.url), { encoding: 'utf-8' }),
       compiler: {
@@ -1461,6 +1464,9 @@ export const fixtures: Fixture[] = [
           { ip: 8, line: 7 },
         ],
         sourceMap: '1::3:1;;::::1;7:23:7:24:0;:16::25:1;;:29::30:0;:8::32:1',
+        functions: [
+          { name: 'sub', inputs: [{ name: 'a', type: 'int' }, { name: 'b', type: 'int' }], bytecode: '94', sourceMap: '2:11:2:16:1', logs: [], requires: [] },
+        ],
       },
       source: fs.readFileSync(new URL('../valid-contract-files/global_function_multi_param.cash', import.meta.url), { encoding: 'utf-8' }),
       compiler: {
@@ -1494,6 +1500,9 @@ export const fixtures: Fixture[] = [
           { ip: 8, line: 8 },
         ],
         sourceMap: '1::3:1;;::::1;7:24:7:25:0;:8::26:1;;8:20:8:23:0;:8::25:1',
+        functions: [
+          { name: 'requirePositive', inputs: [{ name: 'a', type: 'int' }], bytecode: '00a069', sourceMap: '2:16:2:17;:12:::1;:4::19', logs: [], requires: [{ ip: 2, line: 2 }] },
+        ],
       },
       source: fs.readFileSync(new URL('../valid-contract-files/global_function_void.cash', import.meta.url), { encoding: 'utf-8' }),
       compiler: {
@@ -1533,6 +1542,11 @@ export const fixtures: Fixture[] = [
           { ip: 18, line: 6 },
         ],
         sourceMap: '2::4:1;;::::1;1::3::0;;::::1;2::4::0;;::::1;6:19:6:20:0;:16::21:1;;:27::28:0;:24::29:1;;:16;:33::35:0;:8::37:1',
+        functions: [
+          { name: 'm1', inputs: [{ name: 'a', type: 'int' }], bytecode: '518a5295', sourceMap: '3:11:3:18:1;;:21::22:0;:11:::1', logs: [], requires: [], source: fs.readFileSync(new URL('../import-fixtures/mid1.cash', import.meta.url), { encoding: 'utf-8' }), sourceFile: 'mid1.cash' },
+          { name: 'leaf', inputs: [{ name: 'a', type: 'int' }], bytecode: '8b', sourceMap: '2:11:2:16:1', logs: [], requires: [], source: fs.readFileSync(new URL('../import-fixtures/leaf.cash', import.meta.url), { encoding: 'utf-8' }), sourceFile: 'leaf.cash' },
+          { name: 'm2', inputs: [{ name: 'a', type: 'int' }], bytecode: '518a5393', sourceMap: '3:11:3:18:1;;:21::22:0;:11:::1', logs: [], requires: [], source: fs.readFileSync(new URL('../import-fixtures/mid2.cash', import.meta.url), { encoding: 'utf-8' }), sourceFile: 'mid2.cash' },
+        ],
       },
       source: fs.readFileSync(new URL('../import-fixtures/diamond.cash', import.meta.url), { encoding: 'utf-8' }),
       compiler: {

packages/cashscript/src/Errors.ts

@@ -1,4 +1,5 @@
 import { Artifact, RequireStatement, sourceMapToLocationData, Type } from '@cashscript/utils';
+import { ResolvedFrame, rootFrame } from './debug-frame.js';
 
 export class TypeError extends Error {
   constructor(actual: string, expected: Type) {
@@ -134,12 +135,14 @@ export class FailedTransactionEvaluationError extends FailedTransactionError {
     public inputIndex: number,
     public bitauthUri: string,
     public libauthErrorMessage: string,
+    frame?: ResolvedFrame,
   ) {
     let message = `${artifact.contractName}.cash Error in transaction at input ${inputIndex} in contract ${artifact.contractName}.cash.\nReason: ${libauthErrorMessage}`;
 
     if (artifact.debug) {
-      const { statement, lineNumber } = getLocationDataForInstructionPointer(artifact, failingInstructionPointer);
-      message = `${artifact.contractName}.cash:${lineNumber} Error in transaction at input ${inputIndex} in contract ${artifact.contractName}.cash at line ${lineNumber}.\nReason: ${libauthErrorMessage}\nFailing statement: ${statement}`;
+      const resolvedFrame = frame ?? rootFrame(artifact);
+      const { statement, lineNumber } = getLocationDataForFrame(resolvedFrame, failingInstructionPointer);
+      message = `${resolvedFrame.sourceName}:${lineNumber} Error in transaction at input ${inputIndex} in contract ${artifact.contractName}.cash at line ${lineNumber}.\nReason: ${libauthErrorMessage}\nFailing statement: ${statement}`;
     }
 
     super(message, bitauthUri);
@@ -154,10 +157,12 @@ export class FailedRequireError extends FailedTransactionError {
     public inputIndex: number,
     public bitauthUri: string,
     public libauthErrorMessage?: string,
+    frame?: ResolvedFrame,
   ) {
-    const { statement, lineNumber } = getLocationDataForInstructionPointer(artifact, failingInstructionPointer);
+    const resolvedFrame = frame ?? rootFrame(artifact);
+    const { statement, lineNumber } = getLocationDataForFrame(resolvedFrame, failingInstructionPointer);
 
-    const baseMessage = `${artifact.contractName}.cash:${lineNumber} Require statement failed at input ${inputIndex} in contract ${artifact.contractName}.cash at line ${lineNumber}`;
+    const baseMessage = `${resolvedFrame.sourceName}:${lineNumber} Require statement failed at input ${inputIndex} in contract ${artifact.contractName}.cash at line ${lineNumber}`;
     const baseMessageWithRequireMessage = `${baseMessage} with the following message: ${requireStatement.message}`;
     const headline = `${requireStatement.message ? baseMessageWithRequireMessage : baseMessage}.`;
 
@@ -169,19 +174,20 @@ export class FailedRequireError extends FailedTransactionError {
   }
 }
 
-const getLocationDataForInstructionPointer = (
-  artifact: Artifact,
+const getLocationDataForFrame = (
+  frame: ResolvedFrame,
   instructionPointer: number,
 ): { lineNumber: number, statement: string } => {
-  const locationData = sourceMapToLocationData(artifact.debug!.sourceMap);
+  const locationData = sourceMapToLocationData(frame.sourceMap);
 
-  // We subtract the constructor inputs because these are present in the evaluation (and thus the instruction pointer)
-  // but they are not present in the source code (and thus the location data)
-  const modifiedInstructionPointer = instructionPointer - artifact.constructorInputs.length;
+  // 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 = artifact.source.split('\n').slice(location.start.line - 1, location.end.line);
+  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

packages/cashscript/src/debug-frame.ts

@@ -0,0 +1,43 @@
+import { AuthenticationProgramStateCommon, binToHex, encodeAuthenticationInstructions } from '@bitauth/libauth';
+import { Artifact, LogEntry, RequireStatement } from '@cashscript/utils';
+
+export interface ResolvedFrame {
+  sourceMap: string;
+  source: string;
+  sourceName: string;
+  ipOffset: number;
+  requires: readonly RequireStatement[];
+  logs: readonly LogEntry[];
+}
+
+export const rootFrame = (artifact: Artifact): ResolvedFrame => ({
+  sourceMap: artifact.debug?.sourceMap ?? '',
+  source: artifact.source,
+  sourceName: `${artifact.contractName}.cash`,
+  ipOffset: artifact.constructorInputs.length,
+  requires: artifact.debug?.requires ?? [],
+  logs: artifact.debug?.logs ?? [],
+});
+
+export const getActiveBytecode = (step: AuthenticationProgramStateCommon): string =>
+  binToHex(encodeAuthenticationInstructions(step.instructions));
+
+export const resolveFrame = (
+  artifact: Artifact,
+  step: AuthenticationProgramStateCommon,
+): ResolvedFrame => {
+  const frames = artifact.debug?.functions ?? [];
+  const activeBytecode = frames.length > 0 ? getActiveBytecode(step) : undefined;
+  const frame = frames.find((candidate) => candidate.bytecode === activeBytecode);
+
+  if (!frame) return rootFrame(artifact);
+
+  return {
+    sourceMap: frame.sourceMap,
+    source: frame.source ?? artifact.source,
+    sourceName: frame.sourceFile ?? `${artifact.contractName}.cash`,
+    ipOffset: 0, // function bodies have no constructor-arg prefix; their ips start at 0
+    requires: frame.requires,
+    logs: frame.logs,
+  };
+};

packages/cashscript/src/debugging.ts

@@ -2,6 +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 { getActiveBytecode, resolveFrame } from './debug-frame.js';
 import { getBitauthUri } from './libauth-template/LibauthTemplate.js';
 import { VmTarget } from './interfaces.js';
 
@@ -72,7 +73,11 @@ const debugSingleScenario = (
 
   // P2SH executions have 3 phases, we only want the last one (locking script execution)
   // https://libauth.org/types/AuthenticationVirtualMachine.html#__type.debug
-  const lockingScriptDebugResult = fullDebugSteps.slice(findLastIndex(fullDebugSteps, (state) => state.ip === 0));
+  // We additionally require an empty control stack: an invoked function body (OP_INVOKE) also starts at
+  // ip 0, but always with a saved return frame on the control stack.
+  const lockingScriptDebugResult = fullDebugSteps.slice(
+    findLastIndex(fullDebugSteps, (state) => state.ip === 0 && state.controlStack.length === 0),
+  );
 
   // The controlStack determines whether the current debug step is in the executed branch
   // It also tracks loop / function usage, but for the purpose of determining whether a step was executed,
@@ -84,26 +89,29 @@ const debugSingleScenario = (
 
   // P2PKH inputs do not have an artifact, so we skip the console.log handling
   if (artifact) {
-    // Try to match each executed debug step to a log entry if it exists. Note that inside loops,
-    // the same log statement may be executed multiple times in different debug steps
-    // Also note that multiple log statements may exist for the same ip, so we need to handle all of them
+    // Try to match each executed debug step to a log entry if it exists. Notes:
+    // - inside loops, the same log statement may be executed multiple times in different debug steps
+    // - the same ip may be executed by multiple function frames, so they are matched against the active frame's logs.
+    // - multiple log statements may exist for the same ip, so we need to handle all of them.
     const executedLogs = executedDebugSteps
       .flatMap((debugStep, index) => {
-        const logEntries = artifact.debug?.logs?.filter((log) => log.ip === debugStep.ip);
-        if (!logEntries || logEntries.length === 0) return [];
+        const frame = resolveFrame(artifact, debugStep);
+        const logEntries = frame.logs.filter((log) => log.ip === debugStep.ip);
+        if (logEntries.length === 0) return [];
 
         const reversedPriorDebugSteps = executedDebugSteps.slice(0, index + 1).reverse();
+        const frameBytecode = getActiveBytecode(debugStep);
 
         return logEntries.map((logEntry) => {
           const decodedLogData = logEntry.data
-            .map((dataEntry) => decodeLogDataEntry(dataEntry, reversedPriorDebugSteps, vm));
-          return { logEntry, decodedLogData };
+            .map((dataEntry) => decodeLogDataEntry(dataEntry, reversedPriorDebugSteps, vm, frameBytecode));
+          return { logEntry, decodedLogData, sourceName: frame.sourceName };
         });
       });
 
-    for (const { logEntry, decodedLogData } of executedLogs) {
+    for (const { logEntry, decodedLogData, sourceName } of executedLogs) {
       const inputIndex = extractInputIndexFromScenario(scenarioId);
-      logConsoleLogStatement(logEntry, decodedLogData, artifact.contractName, inputIndex);
+      logConsoleLogStatement(logEntry, decodedLogData, sourceName, inputIndex);
     }
   }
 
@@ -135,19 +143,19 @@ const debugSingleScenario = (
       throw new FailedTransactionError(error, getBitauthUri(template));
     }
 
-    const requireStatement = (artifact.debug?.requires ?? [])
-      .find((statement) => statement.ip === requireStatementIp);
+    const frame = resolveFrame(artifact, lastExecutedDebugStep);
+    const requireStatement = frame.requires.find((statement) => statement.ip === requireStatementIp);
 
     if (requireStatement) {
       // Note that we use failingIp here rather than requireStatementIp, see comment above
       throw new FailedRequireError(
-        artifact, failingIp, requireStatement, inputIndex, getBitauthUri(template), error,
+        artifact, failingIp, requireStatement, inputIndex, getBitauthUri(template), error, frame,
       );
     }
 
     // Note that we use failingIp here rather than requireStatementIp, see comment above
     throw new FailedTransactionEvaluationError(
-      artifact, failingIp, inputIndex, getBitauthUri(template), error,
+      artifact, failingIp, inputIndex, getBitauthUri(template), error, frame,
     );
   }
 
@@ -175,17 +183,17 @@ const debugSingleScenario = (
       throw new FailedTransactionError(evaluationResult, getBitauthUri(template));
     }
 
-    const requireStatement = (artifact.debug?.requires ?? [])
-      .find((message) => message.ip === finalExecutedVerifyIp);
+    const frame = resolveFrame(artifact, lastExecutedDebugStep);
+    const requireStatement = frame.requires.find((message) => message.ip === finalExecutedVerifyIp);
 
     if (requireStatement) {
       throw new FailedRequireError(
-        artifact, sourcemapInstructionPointer, requireStatement, inputIndex, getBitauthUri(template),
+        artifact, sourcemapInstructionPointer, requireStatement, inputIndex, getBitauthUri(template), undefined, frame,
       );
     }
 
     throw new FailedTransactionEvaluationError(
-      artifact, sourcemapInstructionPointer, inputIndex, getBitauthUri(template), evaluationResult,
+      artifact, sourcemapInstructionPointer, inputIndex, getBitauthUri(template), evaluationResult, frame,
     );
   }
 
@@ -236,20 +244,23 @@ const createProgram = (template: WalletTemplate, unlockingScriptId: string, scen
 const logConsoleLogStatement = (
   log: LogEntry,
   decodedLogData: Array<string | bigint | boolean>,
-  contractName: string,
+  sourceName: string,
   inputIndex: number,
 ): void => {
-  console.log(`[Input #${inputIndex}] ${contractName}.cash:${log.line} ${decodedLogData.join(' ')}`);
+  console.log(`[Input #${inputIndex}] ${sourceName}:${log.line} ${decodedLogData.join(' ')}`);
 };
 
 const decodeLogDataEntry = (
   dataEntry: LogData,
   reversedPriorDebugSteps: AuthenticationProgramStateCommon[],
   vm: VM,
+  frameBytecode: string,
 ): string | bigint | boolean => {
   if (typeof dataEntry === 'string') return dataEntry;
 
-  const dataEntryDebugStep = reversedPriorDebugSteps.find((step) => step.ip === dataEntry.ip);
+  const dataEntryDebugStep = reversedPriorDebugSteps.find(
+    (step) => step.ip === dataEntry.ip && getActiveBytecode(step) === frameBytecode,
+  );
 
   if (!dataEntryDebugStep) {
     throw new Error(`Should not happen: corresponding data entry debug step not found for entry at ip ${dataEntry.ip}`);

packages/cashscript/src/libauth-template/utils.ts

@@ -77,7 +77,9 @@ export const formatParametersForDebugging = (types: readonly AbiInput[], args: E
 };
 
 export const formatBytecodeForDebugging = (artifact: Artifact): string => {
-  if (!artifact.debug) {
+  // Render the bytecode in true execution order when there is no debug info, or when the contract uses
+  // user-defined functions (TODO: fix source mapping for functions).
+  if (!artifact.debug || (artifact.debug.functions?.length ?? 0) > 0) {
     return artifact.bytecode
       .split(' ')
       .map((asmElement) => (isHex(asmElement) ? `<0x${asmElement}>` : asmElement))