Skip to content

Commit 7591acf

Browse files
ejizbaejizba
authored
Improve invocation hook logs (#571)
1 parent fb42ace commit 7591acf

File tree

3 files changed

+109
-15
lines changed

3 files changed

+109
-15
lines changed

‎src/WorkerChannel.ts‎

Lines changed: 24 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -51,10 +51,31 @@ export class WorkerChannel {
5151
});
5252
}
5353

54-
async executeHooks(hookName: string, context: HookContext): Promise<void> {
54+
async executeHooks(
55+
hookName: string,
56+
context: HookContext,
57+
invocationId?: string | null,
58+
msgCategory?: string
59+
): Promise<void> {
5560
const callbacks = this.#getHooks(hookName);
56-
for (const callback of callbacks) {
57-
await callback(context);
61+
if (callbacks.length > 0) {
62+
this.log({
63+
message: `Executing ${callbacks.length} "${hookName}" hooks`,
64+
level: LogLevel.Debug,
65+
logCategory: LogCategory.System,
66+
invocationId,
67+
category: msgCategory,
68+
});
69+
for (const callback of callbacks) {
70+
await callback(context);
71+
}
72+
this.log({
73+
message: `Executed "${hookName}" hooks`,
74+
level: LogLevel.Debug,
75+
logCategory: LogCategory.System,
76+
invocationId,
77+
category: msgCategory,
78+
});
5879
}
5980
}
6081

‎src/eventHandlers/invocationRequest.ts‎

Lines changed: 14 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -28,25 +28,27 @@ export async function invocationRequest(channel: WorkerChannel, requestId: strin
2828
response.outputData = [];
2929

3030
let isDone = false;
31+
let isExecutingPostInvocationHooks = false;
3132
let resultIsPromise = false;
3233

3334
const info = channel.functionLoader.getInfo(nonNullProp(msg, 'functionId'));
3435
const asyncDoneLearnMoreLink = 'https://go.microsoft.com/fwlink/?linkid=2097909';
3536

36-
function log(level: LogLevel, category: LogCategory, ...args: any[]) {
37+
const msgCategory = `${info.name}.Invocation`;
38+
function log(level: LogLevel, logCategory: LogCategory, ...args: any[]) {
3739
channel.log({
3840
invocationId: msg.invocationId,
39-
category: `${info.name}.Invocation`,
41+
category: msgCategory,
4042
message: format.apply(null, <[any, any[]]>args),
4143
level: level,
42-
logCategory: category,
44+
logCategory,
4345
});
4446
}
4547
function systemLog(level: LogLevel, ...args: any[]) {
4648
log(level, LogCategory.System, ...args);
4749
}
4850
function userLog(level: LogLevel, ...args: any[]) {
49-
if (isDone) {
51+
if (isDone && !isExecutingPostInvocationHooks) {
5052
let badAsyncMsg =
5153
"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. ";
5254
badAsyncMsg += `Function name: ${info.name}. Invocation Id: ${msg.invocationId}. `;
@@ -91,7 +93,7 @@ export async function invocationRequest(channel: WorkerChannel, requestId: strin
9193
inputs,
9294
};
9395

94-
await channel.executeHooks('preInvocation', preInvocContext);
96+
await channel.executeHooks('preInvocation', preInvocContext, msg.invocationId, msgCategory);
9597
inputs = preInvocContext.inputs;
9698
userFunction = preInvocContext.functionCallback;
9799

@@ -120,7 +122,13 @@ export async function invocationRequest(channel: WorkerChannel, requestId: strin
120122
} catch (err) {
121123
postInvocContext.error = err;
122124
}
123-
await channel.executeHooks('postInvocation', postInvocContext);
125+
126+
try {
127+
isExecutingPostInvocationHooks = true;
128+
await channel.executeHooks('postInvocation', postInvocContext, msg.invocationId, msgCategory);
129+
} finally {
130+
isExecutingPostInvocationHooks = false;
131+
}
124132

125133
if (isError(postInvocContext.error)) {
126134
throw postInvocContext.error;

‎test/eventHandlers/invocationRequest.test.ts‎

Lines changed: 71 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -253,6 +253,28 @@ namespace Msg {
253253
},
254254
};
255255
}
256+
export function executingHooksLog(count: number, hookName: string): rpc.IStreamingMessage {
257+
return {
258+
rpcLog: {
259+
category: 'testFuncName.Invocation',
260+
invocationId: '1',
261+
message: `Executing ${count} "${hookName}" hooks`,
262+
level: LogLevel.Debug,
263+
logCategory: LogCategory.System,
264+
},
265+
};
266+
}
267+
export function executedHooksLog(hookName: string): rpc.IStreamingMessage {
268+
return {
269+
rpcLog: {
270+
category: 'testFuncName.Invocation',
271+
invocationId: '1',
272+
message: `Executed "${hookName}" hooks`,
273+
level: LogLevel.Debug,
274+
logCategory: LogCategory.System,
275+
},
276+
};
277+
}
256278
export function invocResponse(
257279
expectedOutputData?: rpc.IParameterBinding[] | null,
258280
expectedReturnValue?: rpc.ITypedData | null
@@ -547,6 +569,8 @@ describe('invocationRequest', () => {
547569
sendInvokeMessage([InputData.http]);
548570
await stream.assertCalledWith(
549571
Msg.receivedInvocLog(),
572+
Msg.executingHooksLog(1, 'preInvocation'),
573+
Msg.executedHooksLog('preInvocation'),
550574
Msg.userTestLog('preinvoc'),
551575
Msg.invocResponse([], { string: 'hello' })
552576
);
@@ -570,6 +594,8 @@ describe('invocationRequest', () => {
570594
sendInvokeMessage([InputData.string]);
571595
await stream.assertCalledWith(
572596
Msg.receivedInvocLog(),
597+
Msg.executingHooksLog(1, 'preInvocation'),
598+
Msg.executedHooksLog('preInvocation'),
573599
Msg.userTestLog('changedStringData'),
574600
Msg.invocResponse([])
575601
);
@@ -592,7 +618,13 @@ describe('invocationRequest', () => {
592618
);
593619

594620
sendInvokeMessage([InputData.string]);
595-
await stream.assertCalledWith(Msg.receivedInvocLog(), Msg.userTestLog('new function'), Msg.invocResponse([]));
621+
await stream.assertCalledWith(
622+
Msg.receivedInvocLog(),
623+
Msg.executingHooksLog(1, 'preInvocation'),
624+
Msg.executedHooksLog('preInvocation'),
625+
Msg.userTestLog('new function'),
626+
Msg.invocResponse([])
627+
);
596628
});
597629

598630
for (const [func, suffix] of TestFunc.logHookData) {
@@ -605,13 +637,17 @@ describe('invocationRequest', () => {
605637
hookData += 'post';
606638
expect(context.result).to.equal('hello');
607639
expect(context.error).to.be.null;
640+
context.invocationContext.log('hello from post');
608641
})
609642
);
610643

611644
sendInvokeMessage([InputData.http]);
612645
await stream.assertCalledWith(
613646
Msg.receivedInvocLog(),
614647
Msg.userTestLog('invoc'),
648+
Msg.executingHooksLog(1, 'postInvocation'),
649+
Msg.userTestLog('hello from post'),
650+
Msg.executedHooksLog('postInvocation'),
615651
Msg.invocResponse([], { string: 'hello' })
616652
);
617653
expect(hookData).to.equal('invocpost');
@@ -636,6 +672,8 @@ describe('invocationRequest', () => {
636672
await stream.assertCalledWith(
637673
Msg.receivedInvocLog(),
638674
Msg.userTestLog('invoc'),
675+
Msg.executingHooksLog(1, 'postInvocation'),
676+
Msg.executedHooksLog('postInvocation'),
639677
Msg.invocResponse([], { string: 'world' })
640678
);
641679
expect(hookData).to.equal('invocpost');
@@ -656,7 +694,12 @@ describe('invocationRequest', () => {
656694
);
657695

658696
sendInvokeMessage([InputData.http]);
659-
await stream.assertCalledWith(Msg.receivedInvocLog(), Msg.invocResFailed);
697+
await stream.assertCalledWith(
698+
Msg.receivedInvocLog(),
699+
Msg.executingHooksLog(1, 'postInvocation'),
700+
Msg.executedHooksLog('postInvocation'),
701+
Msg.invocResFailed
702+
);
660703
expect(hookData).to.equal('post');
661704
});
662705
}
@@ -677,7 +720,12 @@ describe('invocationRequest', () => {
677720
);
678721

679722
sendInvokeMessage([InputData.http]);
680-
await stream.assertCalledWith(Msg.receivedInvocLog(), Msg.invocResponse([], { string: 'hello' }));
723+
await stream.assertCalledWith(
724+
Msg.receivedInvocLog(),
725+
Msg.executingHooksLog(1, 'postInvocation'),
726+
Msg.executedHooksLog('postInvocation'),
727+
Msg.invocResponse([], { string: 'hello' })
728+
);
681729
expect(hookData).to.equal('post');
682730
});
683731
}
@@ -701,7 +749,14 @@ describe('invocationRequest', () => {
701749
);
702750

703751
sendInvokeMessage([InputData.http]);
704-
await stream.assertCalledWith(Msg.receivedInvocLog(), Msg.invocResponse([]));
752+
await stream.assertCalledWith(
753+
Msg.receivedInvocLog(),
754+
Msg.executingHooksLog(1, 'preInvocation'),
755+
Msg.executedHooksLog('preInvocation'),
756+
Msg.executingHooksLog(1, 'postInvocation'),
757+
Msg.executedHooksLog('postInvocation'),
758+
Msg.invocResponse([])
759+
);
705760
expect(hookData).to.equal('prepost');
706761
});
707762

@@ -719,12 +774,22 @@ describe('invocationRequest', () => {
719774
testDisposables.push(disposableB);
720775

721776
sendInvokeMessage([InputData.http]);
722-
await stream.assertCalledWith(Msg.receivedInvocLog(), Msg.invocResponse([]));
777+
await stream.assertCalledWith(
778+
Msg.receivedInvocLog(),
779+
Msg.executingHooksLog(2, 'preInvocation'),
780+
Msg.executedHooksLog('preInvocation'),
781+
Msg.invocResponse([])
782+
);
723783
expect(hookData).to.equal('ab');
724784

725785
disposableA.dispose();
726786
sendInvokeMessage([InputData.http]);
727-
await stream.assertCalledWith(Msg.receivedInvocLog(), Msg.invocResponse([]));
787+
await stream.assertCalledWith(
788+
Msg.receivedInvocLog(),
789+
Msg.executingHooksLog(1, 'preInvocation'),
790+
Msg.executedHooksLog('preInvocation'),
791+
Msg.invocResponse([])
792+
);
728793
expect(hookData).to.equal('abb');
729794

730795
disposableB.dispose();

0 commit comments

Comments
 (0)