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),
+        });
+      });
+    });
+  });
 });

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

@@ -23,7 +23,7 @@ import { createExecutionContainer, ExecutionContainer } from './container';
 import { createError } from '../util';
 import { Defer } from '../../../kibana_utils/common';
 import { RequestAdapter, DataAdapter } from '../../../inspector/common';
-import { isExpressionValueError } from '../expression_types/specs/error';
+import { isExpressionValueError, ExpressionValueError } from '../expression_types/specs/error';
 import {
   ExpressionAstExpression,
   ExpressionAstFunction,
@@ -32,7 +32,7 @@ import {
   parseExpression,
 } from '../ast';
 import { ExecutionContext, DefaultInspectorAdapters } from './types';
-import { getType } from '../expression_types';
+import { getType, ExpressionValue } from '../expression_types';
 import { ArgumentType, ExpressionFunction } from '../expression_functions';
 import { getByAlias } from '../util/get_by_alias';
 import { ExecutionContract } from './execution_contract';
@@ -44,6 +44,13 @@ export interface ExecutionParams<
   ast?: ExpressionAstExpression;
   expression?: string;
   context?: ExtraContext;
+
+  /**
+   * Whether to execute expression in *debug mode*. In *debug mode* inputs and
+   * outputs as well as all resolved arguments and time it took to execute each
+   * function are saved and are available for introspection.
+   */
+  debug?: boolean;
 }
 
 const createDefaultInspectorAdapters = (): DefaultInspectorAdapters => ({
@@ -190,23 +197,55 @@ export class Execution<
       }
 
       const { function: fnName, arguments: fnArgs } = link;
-      const fnDef = getByAlias(this.state.get().functions, fnName);
+      const fn = getByAlias(this.state.get().functions, fnName);
 
-      if (!fnDef) {
+      if (!fn) {
         return createError({ message: `Function ${fnName} could not be found.` });
       }
 
+      let args: Record<string, ExpressionValue> = {};
+      let timeStart: number | undefined;
+
       try {
-        // Resolve arguments before passing to function
-        // resolveArgs returns an object because the arguments themselves might
-        // actually have a 'then' function which would be treated as a promise
-        const { resolvedArgs } = await this.resolveArgs(fnDef, input, fnArgs);
-        const output = await this.invokeFunction(fnDef, input, resolvedArgs);
+        // `resolveArgs` returns an object because the arguments themselves might
+        // actually have a `then` function which would be treated as a `Promise`.
+        const { resolvedArgs } = await this.resolveArgs(fn, input, fnArgs);
+        args = resolvedArgs;
+        timeStart = this.params.debug ? performance.now() : 0;
+        const output = await this.invokeFunction(fn, input, resolvedArgs);
+
+        if (this.params.debug) {
+          const timeEnd: number = performance.now();
+          (link as ExpressionAstFunction).debug = {
+            success: true,
+            fn,
+            input,
+            args: resolvedArgs,
+            output,
+            duration: timeEnd - timeStart,
+          };
+        }
+
         if (getType(output) === 'error') return output;
         input = output;
-      } catch (e) {
-        e.message = `[${fnName}] > ${e.message}`;
-        return createError(e);
+      } catch (rawError) {
+        const timeEnd: number = this.params.debug ? performance.now() : 0;
+        rawError.message = `[${fnName}] > ${rawError.message}`;
+        const error = createError(rawError) as ExpressionValueError;
+
+        if (this.params.debug) {
+          (link as ExpressionAstFunction).debug = {
+            success: false,
+            fn,
+            input,
+            args,
+            error,
+            rawError,
+            duration: timeStart ? timeEnd - timeStart : undefined,
+          };
+        }
+
+        return error;
       }
     }
 
@@ -327,7 +366,9 @@ export class Execution<
     const resolveArgFns = mapValues(argAstsWithDefaults, (asts, argName) => {
       return asts.map((item: ExpressionAstExpression) => {
         return async (subInput = input) => {
-          const output = await this.params.executor.interpret(item, subInput);
+          const output = await this.params.executor.interpret(item, subInput, {
+            debug: this.params.debug,
+          });
           if (isExpressionValueError(output)) throw output.error;
           const casted = this.cast(output, argDefs[argName as any].types);
           return casted;

src/plugins/expressions/common/executor/executor.ts

@@ -31,6 +31,15 @@ import { ExpressionAstExpression, ExpressionAstNode } from '../ast';
 import { typeSpecs } from '../expression_types/specs';
 import { functionSpecs } from '../expression_functions/specs';
 
+export interface ExpressionExecOptions {
+  /**
+   * Whether to execute expression in *debug mode*. In *debug mode* inputs and
+   * outputs as well as all resolved arguments and time it took to execute each
+   * function are saved and are available for introspection.
+   */
+  debug?: boolean;
+}
+
 export class TypesRegistry implements IRegistry<ExpressionType> {
   constructor(private readonly executor: Executor<any>) {}
 
@@ -145,10 +154,14 @@ export class Executor<Context extends Record<string, unknown> = Record<string, u
     return this.state.selectors.getContext();
   }
 
-  public async interpret<T>(ast: ExpressionAstNode, input: T): Promise<unknown> {
+  public async interpret<T>(
+    ast: ExpressionAstNode,
+    input: T,
+    options?: ExpressionExecOptions
+  ): Promise<unknown> {
     switch (getType(ast)) {
       case 'expression':
-        return await this.interpretExpression(ast as ExpressionAstExpression, input);
+        return await this.interpretExpression(ast as ExpressionAstExpression, input, options);
       case 'string':
       case 'number':
       case 'null':
@@ -161,9 +174,10 @@ export class Executor<Context extends Record<string, unknown> = Record<string, u
 
   public async interpretExpression<T>(
     ast: string | ExpressionAstExpression,
-    input: T
+    input: T,
+    options?: ExpressionExecOptions
   ): Promise<unknown> {
-    const execution = this.createExecution(ast);
+    const execution = this.createExecution(ast, undefined, options);
     execution.start(input);
     return await execution.result;
   }
@@ -192,7 +206,8 @@ export class Executor<Context extends Record<string, unknown> = Record<string, u
     Output = unknown
   >(
     ast: string | ExpressionAstExpression,
-    context: ExtraContext = {} as ExtraContext
+    context: ExtraContext = {} as ExtraContext,
+    { debug }: ExpressionExecOptions = {} as ExpressionExecOptions
   ): Execution<Context & ExtraContext, Input, Output> {
     const params: ExecutionParams<Context & ExtraContext> = {
       executor: this,
@@ -200,6 +215,7 @@ export class Executor<Context extends Record<string, unknown> = Record<string, u
         ...this.context,
         ...context,
       } as Context & ExtraContext,
+      debug,
     };
 
     if (typeof ast === 'string') params.expression = ast;