From 7baa893eb8e1d42dc3aad01c68529cecd047871c Mon Sep 17 00:00:00 2001 From: Eric Jizba Date: Wed, 10 Apr 2024 19:33:55 -0700 Subject: [PATCH 1/2] Add hook for logs --- src/AppContext.ts | 1 + src/WorkerContext.ts | 20 ++++++- src/coreApi/converters/toCoreStatusResult.ts | 2 +- src/eventHandlers/InvocationHandler.ts | 20 ++++--- src/hooks/LogHookContext.ts | 57 ++++++++++++++++++++ src/hooks/getHooks.ts | 2 + test/eventHandlers/InvocationHandler.test.ts | 33 ++++++++++++ test/eventHandlers/msg.ts | 4 +- types-core/index.d.ts | 27 +++++++++- 9 files changed, 154 insertions(+), 12 deletions(-) create mode 100644 src/hooks/LogHookContext.ts diff --git a/src/AppContext.ts b/src/AppContext.ts index e729ed36..13e32c0d 100644 --- a/src/AppContext.ts +++ b/src/AppContext.ts @@ -29,6 +29,7 @@ export class AppContext { postInvocationHooks: HookCallback[] = []; appStartHooks: HookCallback[] = []; appTerminateHooks: HookCallback[] = []; + logHooks: HookCallback[] = []; functions: { [id: string]: RegisteredFunction } = {}; legacyFunctions: { [id: string]: LegacyRegisteredFunction } = {}; workerIndexingLocked = false; diff --git a/src/WorkerContext.ts b/src/WorkerContext.ts index b2c02fd1..0e603869 100644 --- a/src/WorkerContext.ts +++ b/src/WorkerContext.ts @@ -4,8 +4,10 @@ import { ProgrammingModel } from '@azure/functions-core'; import { AzureFunctionsRpcMessages as rpc } from '../azure-functions-language-worker-protobuf/src/rpc'; import { AppContext } from './AppContext'; +import { fromCoreLogLevel } from './coreApi/converters/fromCoreStatusResult'; import { AzFuncSystemError } from './errors'; import { IEventStream } from './GrpcClient'; +import { InvocationLogContext, LogHookContext } from './hooks/LogHookContext'; class WorkerContext { app = new AppContext(); @@ -62,7 +64,23 @@ class WorkerContext { * @param requestId gRPC message request id * @param msg gRPC message content */ - log(log: rpc.IRpcLog) { + log(log: rpc.IRpcLog, invocationLogCtx?: InvocationLogContext): void { + try { + const logContext = new LogHookContext(log, invocationLogCtx); + for (const callback of worker.app.logHooks) { + callback(logContext); + } + + if (log.logCategory === rpc.RpcLog.RpcLogCategory.User) { + // let hooks change and filter these values, but only for user-generated logs + // system logs should always be sent as-is + log.message = logContext.message; + log.level = fromCoreLogLevel(logContext.level); + } + } catch { + // ignore so that user hooks can't prevent system logs + } + this.eventStream.write({ rpcLog: log, }); diff --git a/src/coreApi/converters/toCoreStatusResult.ts b/src/coreApi/converters/toCoreStatusResult.ts index 0c9331f9..fe9b99c7 100644 --- a/src/coreApi/converters/toCoreStatusResult.ts +++ b/src/coreApi/converters/toCoreStatusResult.ts @@ -29,7 +29,7 @@ function toCoreLogs(data: rpc.IRpcLog[] | null | undefined): coreTypes.RpcLog[] } } -function toCoreLog(data: rpc.IRpcLog): coreTypes.RpcLog { +export function toCoreLog(data: rpc.IRpcLog): coreTypes.RpcLog { const result = { ...data, level: toCoreLogLevel(data.level), diff --git a/src/eventHandlers/InvocationHandler.ts b/src/eventHandlers/InvocationHandler.ts index 9f77d826..2eb1b84e 100644 --- a/src/eventHandlers/InvocationHandler.ts +++ b/src/eventHandlers/InvocationHandler.ts @@ -21,6 +21,7 @@ import { toCoreFunctionMetadata } from '../coreApi/converters/toCoreFunctionMeta import { toCoreInvocationRequest } from '../coreApi/converters/toCoreInvocationRequest'; import { AzFuncSystemError, isError, ReadOnlyError } from '../errors'; import { executeHooks } from '../hooks/executeHooks'; +import { InvocationLogContext } from '../hooks/LogHookContext'; import { getLegacyFunction } from '../LegacyFunctionLoader'; import { nonNullProp } from '../utils/nonNull'; import { worker } from '../WorkerContext'; @@ -70,6 +71,7 @@ export class InvocationHandler extends EventHandler<'invocationRequest', 'invoca const hookData: HookData = {}; let { context, inputs } = await invocModel.getArguments(); + coreCtx.logContext = { hookData, invocationContext: context }; const preInvocContext: PreInvocationContext = { get hookData() { @@ -157,6 +159,7 @@ class CoreInvocationContext implements coreTypes.CoreInvocationContext { request: RpcInvocationRequest; metadata: RpcFunctionMetadata; state?: InvocationState; + logContext?: InvocationLogContext; #msgCategory: string; constructor(request: RpcInvocationRequest, metadata: RpcFunctionMetadata, msgCategory: string) { @@ -167,12 +170,15 @@ class CoreInvocationContext implements coreTypes.CoreInvocationContext { } log(level: RpcLogLevel, logCategory: RpcLogCategory, message: string): void { - worker.log({ - invocationId: this.request.invocationId, - category: this.#msgCategory, - message, - level: fromCoreLogLevel(level), - logCategory: fromCoreLogCategory(logCategory), - }); + worker.log( + { + invocationId: this.request.invocationId, + category: this.#msgCategory, + message, + level: fromCoreLogLevel(level), + logCategory: fromCoreLogCategory(logCategory), + }, + this.logContext + ); } } diff --git a/src/hooks/LogHookContext.ts b/src/hooks/LogHookContext.ts new file mode 100644 index 00000000..aee4780b --- /dev/null +++ b/src/hooks/LogHookContext.ts @@ -0,0 +1,57 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. + +import { HookData, RpcLogCategory, RpcLogLevel } from '@azure/functions-core'; +import * as coreTypes from '@azure/functions-core'; +import { AzureFunctionsRpcMessages as rpc } from '../../azure-functions-language-worker-protobuf/src/rpc'; +import { toCoreLog } from '../coreApi/converters/toCoreStatusResult'; +import { ReadOnlyError } from '../errors'; +import { nonNullProp } from '../utils/nonNull'; +import { worker } from '../WorkerContext'; + +export interface InvocationLogContext { + hookData: HookData; + invocationContext: unknown; +} + +export class LogHookContext implements coreTypes.LogHookContext { + level: RpcLogLevel; + message: string; + #hookData: HookData; + #category: RpcLogCategory; + #invocationContext: unknown; + + constructor(log: rpc.IRpcLog, invocLogCtx: InvocationLogContext | undefined) { + this.#hookData = invocLogCtx?.hookData ?? {}; + this.#invocationContext = invocLogCtx?.invocationContext; + const coreLog = toCoreLog(log); + this.level = nonNullProp(coreLog, 'level'); + this.message = nonNullProp(coreLog, 'message'); + this.#category = nonNullProp(coreLog, 'logCategory'); + } + + get hookData(): HookData { + return this.#hookData; + } + set hookData(_obj: HookData) { + throw new ReadOnlyError('hookData'); + } + get category(): RpcLogCategory { + return this.#category; + } + set category(_obj: RpcLogCategory) { + throw new ReadOnlyError('category'); + } + get appHookData(): HookData { + return worker.app.appHookData; + } + set appHookData(_obj: HookData) { + throw new ReadOnlyError('appHookData'); + } + get invocationContext(): unknown { + return this.#invocationContext; + } + set invocationContext(_obj: unknown) { + throw new ReadOnlyError('invocationContext'); + } +} diff --git a/src/hooks/getHooks.ts b/src/hooks/getHooks.ts index 8a951289..a1a8c3a9 100644 --- a/src/hooks/getHooks.ts +++ b/src/hooks/getHooks.ts @@ -15,6 +15,8 @@ export function getHooks(hookName: string): HookCallback[] { return worker.app.appStartHooks; case 'appTerminate': return worker.app.appTerminateHooks; + case 'log': + return worker.app.logHooks; default: throw new AzFuncRangeError(`Unrecognized hook "${hookName}"`); } diff --git a/test/eventHandlers/InvocationHandler.test.ts b/test/eventHandlers/InvocationHandler.test.ts index 2265ec5c..d4f3219f 100644 --- a/test/eventHandlers/InvocationHandler.test.ts +++ b/test/eventHandlers/InvocationHandler.test.ts @@ -1063,4 +1063,37 @@ describe('InvocationHandler', () => { msg.invocation.response([]) ); }); + + it('log hook respects changes to value, only for user log', async () => { + coreApi.registerHook('log', (ctx) => { + ctx.message += 'UpdatedFromHook'; + ctx.level = 'error'; + }); + + registerV3Func(Binding.queue, async (invocContext: Context) => { + invocContext.log('testUserLog'); + }); + stream.addTestMessage(msg.invocation.request([InputData.http])); + await stream.assertCalledWith( + msg.invocation.receivedRequestLog, + msg.invocation.userLog('testUserLogUpdatedFromHook', LogLevel.Error), + msg.invocation.response([]) + ); + }); + + it('ignores log hook error', async () => { + coreApi.registerHook('log', (_ctx) => { + throw new Error('failed log hook'); + }); + + registerV3Func(Binding.queue, async (invocContext: Context) => { + invocContext.log('testUserLog'); + }); + stream.addTestMessage(msg.invocation.request([InputData.http])); + await stream.assertCalledWith( + msg.invocation.receivedRequestLog, + msg.invocation.userLog(), + msg.invocation.response([]) + ); + }); }); diff --git a/test/eventHandlers/msg.ts b/test/eventHandlers/msg.ts index 0a865b39..da6e6a4f 100644 --- a/test/eventHandlers/msg.ts +++ b/test/eventHandlers/msg.ts @@ -381,13 +381,13 @@ export namespace msg { "Warning: Unexpected call to 'log' on the context object after function execution has completed. Please check for asynchronous calls that are not awaited or calls to 'done' made before function execution completes. Function name: testFuncName. Invocation Id: 1. Learn more: https://go.microsoft.com/fwlink/?linkid=2097909" ); - export function userLog(data = 'testUserLog'): TestMessage { + export function userLog(data = 'testUserLog', level = LogLevel.Information): TestMessage { return { rpcLog: { category: 'testFuncName.Invocation', invocationId: '1', message: data, - level: LogLevel.Information, + level, logCategory: LogCategory.User, }, }; diff --git a/types-core/index.d.ts b/types-core/index.d.ts index e5e394f6..2fb35060 100644 --- a/types-core/index.d.ts +++ b/types-core/index.d.ts @@ -58,13 +58,15 @@ declare module '@azure/functions-core' { function registerHook(hookName: 'postInvocation', callback: PostInvocationCallback): Disposable; function registerHook(hookName: 'appStart', callback: AppStartCallback): Disposable; function registerHook(hookName: 'appTerminate', callback: AppTerminateCallback): Disposable; + function registerHook(hookName: 'log', callback: LogHookCallback): Disposable; function registerHook(hookName: string, callback: HookCallback): Disposable; - type HookCallback = (context: HookContext) => void | Promise; + type HookCallback = (context: HookContext) => unknown; type PreInvocationCallback = (context: PreInvocationContext) => void | Promise; type PostInvocationCallback = (context: PostInvocationContext) => void | Promise; type AppStartCallback = (context: AppStartContext) => void | Promise; type AppTerminateCallback = (context: AppTerminateContext) => void | Promise; + type LogHookCallback = (context: LogHookContext) => void; type HookData = { [key: string]: any }; @@ -146,6 +148,29 @@ declare module '@azure/functions-core' { type AppTerminateContext = HookContext; + interface LogHookContext extends HookContext { + /** + * If the log occurs during a function execution, the context object passed to the function handler. + * Otherwise, undefined. + */ + readonly invocationContext?: unknown; + + /** + * 'system' if the log is generated by Azure Functions, 'user' if the log is generated by your own app. + */ + readonly category: RpcLogCategory; + + /** + * Changes to this value _will_ affect the resulting log, but only for user-generated logs. + */ + level: RpcLogLevel; + + /** + * Changes to this value _will_ affect the resulting log, but only for user-generated logs. + */ + message: string; + } + /** * Represents a type which can release resources, such as event listening or a timer. */ From 5e2d965f1810a5e8a136ca02e4ed9a1824c90470 Mon Sep 17 00:00:00 2001 From: Eric Jizba Date: Thu, 11 Apr 2024 10:37:42 -0700 Subject: [PATCH 2/2] feedback --- src/hooks/LogHookContext.ts | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/hooks/LogHookContext.ts b/src/hooks/LogHookContext.ts index aee4780b..cc56495c 100644 --- a/src/hooks/LogHookContext.ts +++ b/src/hooks/LogHookContext.ts @@ -17,17 +17,17 @@ export interface InvocationLogContext { export class LogHookContext implements coreTypes.LogHookContext { level: RpcLogLevel; message: string; - #hookData: HookData; #category: RpcLogCategory; + #hookData: HookData; #invocationContext: unknown; constructor(log: rpc.IRpcLog, invocLogCtx: InvocationLogContext | undefined) { - this.#hookData = invocLogCtx?.hookData ?? {}; - this.#invocationContext = invocLogCtx?.invocationContext; const coreLog = toCoreLog(log); this.level = nonNullProp(coreLog, 'level'); this.message = nonNullProp(coreLog, 'message'); this.#category = nonNullProp(coreLog, 'logCategory'); + this.#hookData = invocLogCtx?.hookData ?? {}; + this.#invocationContext = invocLogCtx?.invocationContext; } get hookData(): HookData {