Expressions debug mode (#57841)

* feat: 🎸 add ability to execute expression in debug mode

* feat: 🎸 store resolved arguments in debug information

* feat: 🎸 track function execution time and set "success" flag

* feat: 🎸 store debug information for functions that throw

* feat: 🎸 use performance.now, safe "fn" reference, fix typo

src/plugins/expressions/common/ast/types.ts

@@ -17,6 +17,9 @@
  * under the License.
  */
 
+import { ExpressionValue, ExpressionValueError } from '../expression_types';
+import { ExpressionFunction } from '../../public';
+
 export type ExpressionAstNode =
   | ExpressionAstExpression
   | ExpressionAstFunction
@@ -31,6 +34,56 @@ export interface ExpressionAstFunction {
   type: 'function';
   function: string;
   arguments: Record<string, ExpressionAstArgument[]>;
+
+  /**
+   * Debug information added to each function when expression is executed in *debug mode*.
+   */
+  debug?: ExpressionAstFunctionDebug;
+}
+
+export interface ExpressionAstFunctionDebug {
+  /**
+   * True if function successfully returned output, false if function threw.
+   */
+  success: boolean;
+
+  /**
+   * Reference to the expression function this AST node represents.
+   */
+  fn: ExpressionFunction;
+
+  /**
+   * Input that expression function received as its first argument.
+   */
+  input: ExpressionValue;
+
+  /**
+   * Map of resolved arguments expression function received as its second argument.
+   */
+  args: Record<string, ExpressionValue>;
+
+  /**
+   * Result returned by the expression function. Including an error result
+   * if it was returned by the function (not thrown).
+   */
+  output?: ExpressionValue;
+
+  /**
+   * Error that function threw normalized to `ExpressionValueError`.
+   */
+  error?: ExpressionValueError;
+
+  /**
+   * Raw error that was thrown by the function, if any.
+   */
+  rawError?: any | Error;
+
+  /**
+   * Time in milliseconds it took to execute the function. Duration can be
+   * `undefined` if error happened during argument resolution, because function
+   * timing starts after the arguments have been resolved.
+   */
+  duration: number | undefined;
 }
 
 export type ExpressionAstArgument = string | boolean | number | ExpressionAstExpression;

src/plugins/expressions/common/execution/execution.test.ts

@@ -18,20 +18,28 @@
  */
 
 import { Execution } from './execution';
-import { parseExpression } from '../ast';
+import { parseExpression, ExpressionAstExpression } from '../ast';
 import { createUnitTestExecutor } from '../test_helpers';
 import { ExpressionFunctionDefinition } from '../../public';
 import { ExecutionContract } from './execution_contract';
 
+beforeAll(() => {
+  if (typeof performance === 'undefined') {
+    (global as any).performance = { now: Date.now };
+  }
+});
+
 const createExecution = (
   expression: string = 'foo bar=123',
-  context: Record<string, unknown> = {}
+  context: Record<string, unknown> = {},
+  debug: boolean = false
 ) => {
   const executor = createUnitTestExecutor();
   const execution = new Execution({
     executor,
     ast: parseExpression(expression),
     context,
+    debug,
   });
   return execution;
 };
@@ -406,4 +414,245 @@ describe('Execution', () => {
       });
     });
   });
+
+  describe('debug mode', () => {
+    test('can execute expression in debug mode', async () => {
+      const execution = createExecution('add val=1 | add val=2 | add val=3', {}, true);
+      execution.start(-1);
+      const result = await execution.result;
+
+      expect(result).toEqual({
+        type: 'num',
+        value: 5,
+      });
+    });
+
+    test('can execute expression with sub-expression in debug mode', async () => {
+      const execution = createExecution(
+        'add val={var_set name=foo value=5 | var name=foo} | add val=10',
+        {},
+        true
+      );
+      execution.start(0);
+      const result = await execution.result;
+
+      expect(result).toEqual({
+        type: 'num',
+        value: 15,
+      });
+    });
+
+    describe('when functions succeed', () => {
+      test('sets "success" flag on all functions to true', async () => {
+        const execution = createExecution('add val=1 | add val=2 | add val=3', {}, true);
+        execution.start(-1);
+        await execution.result;
+
+        for (const node of execution.state.get().ast.chain) {
+          expect(node.debug?.success).toBe(true);
+        }
+      });
+
+      test('stores "fn" reference to the function', async () => {
+        const execution = createExecution('add val=1 | add val=2 | add val=3', {}, true);
+        execution.start(-1);
+        await execution.result;
+
+        for (const node of execution.state.get().ast.chain) {
+          expect(node.debug?.fn.name).toBe('add');
+        }
+      });
+
+      test('saves duration it took to execute each function', async () => {
+        const execution = createExecution('add val=1 | add val=2 | add val=3', {}, true);
+        execution.start(-1);
+        await execution.result;
+
+        for (const node of execution.state.get().ast.chain) {
+          expect(typeof node.debug?.duration).toBe('number');
+          expect(node.debug?.duration).toBeLessThan(100);
+          expect(node.debug?.duration).toBeGreaterThanOrEqual(0);
+        }
+      });
+
+      test('sets duration to 10 milliseconds when function executes 10 milliseconds', async () => {
+        const execution = createExecution('sleep 10', {}, true);
+        execution.start(-1);
+        await execution.result;
+
+        const node = execution.state.get().ast.chain[0];
+        expect(typeof node.debug?.duration).toBe('number');
+        expect(node.debug?.duration).toBeLessThan(50);
+        expect(node.debug?.duration).toBeGreaterThanOrEqual(5);
+      });
+
+      test('adds .debug field in expression AST on each executed function', async () => {
+        const execution = createExecution('add val=1 | add val=2 | add val=3', {}, true);
+        execution.start(-1);
+        await execution.result;
+
+        for (const node of execution.state.get().ast.chain) {
+          expect(typeof node.debug).toBe('object');
+          expect(!!node.debug).toBe(true);
+        }
+      });
+
+      test('stores input of each function', async () => {
+        const execution = createExecution('add val=1 | add val=2 | add val=3', {}, true);
+        execution.start(-1);
+        await execution.result;
+
+        const { chain } = execution.state.get().ast;
+
+        expect(chain[0].debug!.input).toBe(-1);
+        expect(chain[1].debug!.input).toEqual({
+          type: 'num',
+          value: 0,
+        });
+        expect(chain[2].debug!.input).toEqual({
+          type: 'num',
+          value: 2,
+        });
+      });
+
+      test('stores output of each function', async () => {
+        const execution = createExecution('add val=1 | add val=2 | add val=3', {}, true);
+        execution.start(-1);
+        await execution.result;
+
+        const { chain } = execution.state.get().ast;
+
+        expect(chain[0].debug!.output).toEqual({
+          type: 'num',
+          value: 0,
+        });
+        expect(chain[1].debug!.output).toEqual({
+          type: 'num',
+          value: 2,
+        });
+        expect(chain[2].debug!.output).toEqual({
+          type: 'num',
+          value: 5,
+        });
+      });
+
+      test('stores resolved arguments of a function', async () => {
+        const execution = createExecution(
+          'add val={var_set name=foo value=5 | var name=foo} | add val=10',
+          {},
+          true
+        );
+        execution.start(-1);
+        await execution.result;
+
+        const { chain } = execution.state.get().ast;
+
+        expect(chain[0].debug!.args).toEqual({
+          val: 5,
+        });
+
+        expect((chain[0].arguments.val[0] as ExpressionAstExpression).chain[0].debug!.args).toEqual(
+          {
+            name: 'foo',
+            value: 5,
+          }
+        );
+      });
+
+      test('store debug information about sub-expressions', async () => {
+        const execution = createExecution(
+          'add val={var_set name=foo value=5 | var name=foo} | add val=10',
+          {},
+          true
+        );
+        execution.start(0);
+        await execution.result;
+
+        const { chain } = execution.state.get().ast.chain[0].arguments
+          .val[0] as ExpressionAstExpression;
+
+        expect(typeof chain[0].debug).toBe('object');
+        expect(typeof chain[1].debug).toBe('object');
+        expect(!!chain[0].debug).toBe(true);
+        expect(!!chain[1].debug).toBe(true);
+
+        expect(chain[0].debug!.input).toBe(0);
+        expect(chain[0].debug!.output).toBe(0);
+        expect(chain[1].debug!.input).toBe(0);
+        expect(chain[1].debug!.output).toBe(5);
+      });
+    });
+
+    describe('when expression throws', () => {
+      const executor = createUnitTestExecutor();
+      executor.registerFunction({
+        name: 'throws',
+        args: {},
+        help: '',
+        fn: () => {
+          throw new Error('foo');
+        },
+      });
+
+      test('stores debug information up until the function that throws', async () => {
+        const execution = new Execution({
+          executor,
+          ast: parseExpression('add val=1 | throws | add val=3'),
+          debug: true,
+        });
+        execution.start(0);
+        await execution.result;
+
+        const node1 = execution.state.get().ast.chain[0];
+        const node2 = execution.state.get().ast.chain[1];
+        const node3 = execution.state.get().ast.chain[2];
+
+        expect(typeof node1.debug).toBe('object');
+        expect(typeof node2.debug).toBe('object');
+        expect(typeof node3.debug).toBe('undefined');
+      });
+
+      test('stores error thrown in debug information', async () => {
+        const execution = new Execution({
+          executor,
+          ast: parseExpression('add val=1 | throws | add val=3'),
+          debug: true,
+        });
+        execution.start(0);
+        await execution.result;
+
+        const node2 = execution.state.get().ast.chain[1];
+
+        expect(node2.debug?.error).toMatchObject({
+          type: 'error',
+          error: {
+            message: '[throws] > foo',
+          },
+        });
+        expect(node2.debug?.rawError).toBeInstanceOf(Error);
+      });
+
+      test('sets .debug object to expected shape', async () => {
+        const execution = new Execution({
+          executor,
+          ast: parseExpression('add val=1 | throws | add val=3'),
+          debug: true,
+        });
+        execution.start(0);
+        await execution.result;
+
+        const node2 = execution.state.get().ast.chain[1];
+
+        expect(node2.debug).toMatchObject({
+          success: false,
+          fn: expect.any(Object),
+          input: expect.any(Object),
+          args: expect.any(Object),
+          error: expect.any(Object),
+          rawError: expect.any(Error),
+          duration: expect.any(Number),
+        });
+      });
+    });
+  });
 });