diff --git a/src/plugins/expressions/common/ast/types.ts b/src/plugins/expressions/common/ast/types.ts index 82a7578dd4b89..0b505f117a580 100644 --- a/src/plugins/expressions/common/ast/types.ts +++ b/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; + + /** + * 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; + + /** + * 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; diff --git a/src/plugins/expressions/common/execution/execution.test.ts b/src/plugins/expressions/common/execution/execution.test.ts index b6c1721e33eef..f6ff9efca848b 100644 --- a/src/plugins/expressions/common/execution/execution.test.ts +++ b/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 = {} + context: Record = {}, + 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), + }); + }); + }); + }); }); diff --git a/src/plugins/expressions/common/execution/execution.ts b/src/plugins/expressions/common/execution/execution.ts index 2a272e187cffc..7e7df822724ae 100644 --- a/src/plugins/expressions/common/execution/execution.ts +++ b/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 = {}; + 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; diff --git a/src/plugins/expressions/common/executor/executor.ts b/src/plugins/expressions/common/executor/executor.ts index af3662d13de4e..2ecbc5f75a9e8 100644 --- a/src/plugins/expressions/common/executor/executor.ts +++ b/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 { constructor(private readonly executor: Executor) {} @@ -145,10 +154,14 @@ export class Executor = Record(ast: ExpressionAstNode, input: T): Promise { + public async interpret( + ast: ExpressionAstNode, + input: T, + options?: ExpressionExecOptions + ): Promise { 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 = Record( ast: string | ExpressionAstExpression, - input: T + input: T, + options?: ExpressionExecOptions ): Promise { - 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 = Record( ast: string | ExpressionAstExpression, - context: ExtraContext = {} as ExtraContext + context: ExtraContext = {} as ExtraContext, + { debug }: ExpressionExecOptions = {} as ExpressionExecOptions ): Execution { const params: ExecutionParams = { executor: this, @@ -200,6 +215,7 @@ export class Executor = Record