Add hook for logs (#739)

Author: ejizba

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;

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

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),

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

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;
+    #category: RpcLogCategory;
+    #hookData: HookData;
+    #invocationContext: unknown;
+
+    constructor(log: rpc.IRpcLog, invocLogCtx: InvocationLogContext | undefined) {
+        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 {
+        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');
+    }
+}

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}"`);
     }

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([])
+        );
+    });
 });

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

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<void>;
+    type HookCallback = (context: HookContext) => unknown;
     type PreInvocationCallback = (context: PreInvocationContext) => void | Promise<void>;
     type PostInvocationCallback = (context: PostInvocationContext) => void | Promise<void>;
     type AppStartCallback = (context: AppStartContext) => void | Promise<void>;
     type AppTerminateCallback = (context: AppTerminateContext) => void | Promise<void>;
+    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.
      */