Warn users with long load times (#660)

ejizba · web-flow · commit 07e5356a59e3 · 2023-03-02T11:35:01.000-08:00
and tell them to use WEBSITE_RUN_FROM_PACKAGE
diff --git a/src/LegacyFunctionLoader.ts b/src/LegacyFunctionLoader.ts
@@ -7,10 +7,15 @@ import { AzFuncSystemError } from './errors';
 import { loadScriptFile } from './loadScriptFile';
 import { PackageJson } from './parsers/parsePackageJson';
 import { nonNullProp } from './utils/nonNull';
-import { RegisteredFunction } from './WorkerChannel';
+import { RegisteredFunction, WorkerChannel } from './WorkerChannel';
 
 export interface ILegacyFunctionLoader {
-    load(functionId: string, metadata: rpc.IRpcFunctionMetadata, packageJson: PackageJson): Promise<void>;
+    load(
+        channel: WorkerChannel,
+        functionId: string,
+        metadata: rpc.IRpcFunctionMetadata,
+        packageJson: PackageJson
+    ): Promise<void>;
     getFunction(functionId: string): RegisteredFunction | undefined;
 }
 
@@ -21,11 +26,16 @@ interface LegacyRegisteredFunction extends RegisteredFunction {
 export class LegacyFunctionLoader implements ILegacyFunctionLoader {
     #loadedFunctions: { [k: string]: LegacyRegisteredFunction | undefined } = {};
 
-    async load(functionId: string, metadata: rpc.IRpcFunctionMetadata, packageJson: PackageJson): Promise<void> {
+    async load(
+        channel: WorkerChannel,
+        functionId: string,
+        metadata: rpc.IRpcFunctionMetadata,
+        packageJson: PackageJson
+    ): Promise<void> {
         if (metadata.isProxy === true) {
             return;
         }
-        const script: any = await loadScriptFile(nonNullProp(metadata, 'scriptFile'), packageJson);
+        const script: any = await loadScriptFile(channel, nonNullProp(metadata, 'scriptFile'), packageJson);
         const entryPoint = <string>(metadata && metadata.entryPoint);
         const [callback, thisArg] = getEntryPoint(script, entryPoint);
         this.#loadedFunctions[functionId] = { metadata, callback, thisArg };
diff --git a/src/eventHandlers/FunctionLoadHandler.ts b/src/eventHandlers/FunctionLoadHandler.ts
@@ -34,7 +34,7 @@ export class FunctionLoadHandler extends EventHandler<'functionLoadRequest', 'fu
             const functionId = nonNullProp(msg, 'functionId');
             const metadata = nonNullProp(msg, 'metadata');
             try {
-                await channel.legacyFunctionLoader.load(functionId, metadata, channel.packageJson);
+                await channel.legacyFunctionLoader.load(channel, functionId, metadata, channel.packageJson);
             } catch (err) {
                 const error = ensureErrorType(err);
                 error.isAzureFunctionsSystemError = true;
diff --git a/src/loadScriptFile.ts b/src/loadScriptFile.ts
@@ -1,24 +1,56 @@
 // Copyright (c) .NET Foundation. All rights reserved.
 // Licensed under the MIT License.
 
+import * as path from 'path';
 import * as url from 'url';
+import { AzureFunctionsRpcMessages as rpc } from '../azure-functions-language-worker-protobuf/src/rpc';
 import { AzFuncSystemError } from './errors';
 import { PackageJson } from './parsers/parsePackageJson';
+import { WorkerChannel } from './WorkerChannel';
+import LogCategory = rpc.RpcLog.RpcLogCategory;
+import LogLevel = rpc.RpcLog.Level;
 
-export async function loadScriptFile(filePath: string, packageJson: PackageJson): Promise<unknown> {
-    let script: unknown;
-    if (isESModule(filePath, packageJson)) {
-        const fileUrl = url.pathToFileURL(filePath);
-        if (fileUrl.href) {
-            // use eval so it doesn't get compiled into a require()
-            script = await eval('import(fileUrl.href)');
+export async function loadScriptFile(
+    channel: WorkerChannel,
+    filePath: string,
+    packageJson: PackageJson
+): Promise<unknown> {
+    const start = Date.now();
+    try {
+        let script: unknown;
+        if (isESModule(filePath, packageJson)) {
+            const fileUrl = url.pathToFileURL(filePath);
+            if (fileUrl.href) {
+                // use eval so it doesn't get compiled into a require()
+                script = await eval('import(fileUrl.href)');
+            } else {
+                throw new AzFuncSystemError(`'${filePath}' could not be converted to file URL (${fileUrl.href})`);
+            }
         } else {
-            throw new AzFuncSystemError(`'${filePath}' could not be converted to file URL (${fileUrl.href})`);
+            script = require(/* webpackIgnore: true */ filePath);
         }
-    } else {
-        script = require(/* webpackIgnore: true */ filePath);
+        return script;
+    } finally {
+        warnIfLongLoadTime(channel, filePath, start);
+    }
+}
+
+function warnIfLongLoadTime(channel: WorkerChannel, filePath: string, start: number): void {
+    const timeElapsed = Date.now() - start;
+    const rfpName = 'WEBSITE_RUN_FROM_PACKAGE';
+    const rfpValue = process.env[rfpName];
+    if (timeElapsed > 1000 && (rfpValue === undefined || rfpValue === '0')) {
+        channel.log({
+            message: `Loading "${path.basename(filePath)}" took ${timeElapsed}ms`,
+            level: LogLevel.Warning,
+            logCategory: LogCategory.System,
+        });
+        channel.log({
+            message: `Set "${rfpName}" to "1" to significantly improve load times. Learn more here: https://aka.ms/AAjon54`,
+            level: LogLevel.Warning,
+            logCategory: LogCategory.System,
+        });
     }
-    return script;
 }
 
 export function isESModule(filePath: string, packageJson: PackageJson): boolean {
diff --git a/src/startApp.ts b/src/startApp.ts
@@ -58,7 +58,7 @@ async function loadEntryPointFile(functionAppDirectory: string, channel: WorkerC
                 try {
                     const entryPointFilePath = path.join(functionAppDirectory, file);
                     channel.currentEntryPoint = entryPointFilePath;
-                    await loadScriptFile(entryPointFilePath, channel.packageJson);
+                    await loadScriptFile(channel, entryPointFilePath, channel.packageJson);
                 } finally {
                     channel.currentEntryPoint = undefined;
                 }
diff --git a/test/LegacyFunctionLoader.test.ts b/test/LegacyFunctionLoader.test.ts
@@ -5,15 +5,18 @@ import * as chai from 'chai';
 import * as chaiAsPromised from 'chai-as-promised';
 import 'mocha';
 import * as mock from 'mock-require';
+import * as sinon from 'sinon';
 import { AzureFunctionsRpcMessages as rpc } from '../azure-functions-language-worker-protobuf/src/rpc';
 import { LegacyFunctionLoader } from '../src/LegacyFunctionLoader';
 import { nonNullValue } from '../src/utils/nonNull';
+import { WorkerChannel } from '../src/WorkerChannel';
 const expect = chai.expect;
 chai.use(chaiAsPromised);
 
 describe('LegacyFunctionLoader', () => {
     let loader: LegacyFunctionLoader;
     let context, logs;
+    const channel: WorkerChannel = <WorkerChannel>(<any>sinon.createStubInstance(WorkerChannel));
 
     beforeEach(() => {
         loader = new LegacyFunctionLoader();
@@ -32,6 +35,7 @@ describe('LegacyFunctionLoader', () => {
         mock('test', {});
         await expect(
             loader.load(
+                channel,
                 'functionId',
                 <rpc.IRpcFunctionMetadata>{
                     scriptFile: 'test',
@@ -46,6 +50,7 @@ describe('LegacyFunctionLoader', () => {
     it('does not load proxy function', async () => {
         mock('test', {});
         await loader.load(
+            channel,
             'functionId',
             <rpc.IRpcFunctionMetadata>{
                 isProxy: true,
@@ -61,6 +66,7 @@ describe('LegacyFunctionLoader', () => {
         const entryPoint = 'wrongEntryPoint';
         await expect(
             loader.load(
+                channel,
                 'functionId',
                 <rpc.IRpcFunctionMetadata>{
                     scriptFile: 'test',
@@ -78,6 +84,7 @@ describe('LegacyFunctionLoader', () => {
         const entryPoint = 'test';
         await expect(
             loader.load(
+                channel,
                 'functionId',
                 <rpc.IRpcFunctionMetadata>{
                     scriptFile: 'test',
@@ -109,6 +116,7 @@ describe('LegacyFunctionLoader', () => {
         mock('test', new FuncObject());
 
         await loader.load(
+            channel,
             'functionId',
             <rpc.IRpcFunctionMetadata>{
                 scriptFile: 'test',
@@ -127,6 +135,7 @@ describe('LegacyFunctionLoader', () => {
         mock('test', { test: async () => {} });
 
         await loader.load(
+            channel,
             'functionId',
             <rpc.IRpcFunctionMetadata>{
                 scriptFile: 'test',
@@ -146,6 +155,7 @@ describe('LegacyFunctionLoader', () => {
         mock('test', { test: async () => {} });
 
         await loader.load(
+            channel,
             'functionId',
             <rpc.IRpcFunctionMetadata>{
                 scriptFile: 'test',
diff --git a/test/eventHandlers/FunctionLoadHandler.test.ts b/test/eventHandlers/FunctionLoadHandler.test.ts
@@ -6,6 +6,7 @@ import * as sinon from 'sinon';
 import { AzureFunctionsRpcMessages as rpc } from '../../azure-functions-language-worker-protobuf/src/rpc';
 import { LegacyFunctionLoader } from '../../src/LegacyFunctionLoader';
 import { PackageJson } from '../../src/parsers/parsePackageJson';
+import { WorkerChannel } from '../../src/WorkerChannel';
 import { beforeEventHandlerSuite } from './beforeEventHandlerSuite';
 import { TestEventStream } from './TestEventStream';
 import LogCategory = rpc.RpcLog.RpcLogCategory;
@@ -58,7 +59,9 @@ describe('FunctionLoadHandler', () => {
 
         const originalLoader = loader.load;
         try {
-            loader.load = sinon.stub<[string, rpc.IRpcFunctionMetadata, PackageJson], Promise<void>>().throws(err);
+            loader.load = sinon
+                .stub<[WorkerChannel, string, rpc.IRpcFunctionMetadata, PackageJson], Promise<void>>()
+                .throws(err);
 
             stream.addTestMessage({
                 requestId: 'id',
diff --git a/test/eventHandlers/TestEventStream.ts b/test/eventHandlers/TestEventStream.ts
@@ -3,6 +3,7 @@
 
 import { expect } from 'chai';
 import { EventEmitter } from 'events';
+import * as path from 'path';
 import * as sinon from 'sinon';
 import { AzureFunctionsRpcMessages as rpc } from '../../azure-functions-language-worker-protobuf/src/rpc';
 import { IEventStream } from '../../src/GrpcClient';
@@ -41,9 +42,12 @@ export class TestEventStream extends EventEmitter implements IEventStream {
             const calls = this.written.getCalls();
 
             // First, validate the "shortened" form of the messages. This will result in a more readable error for most test failures
-            const shortExpectedMsgs = expectedMsgs.map(getShortenedMsg);
-            const shortActualMsgs = calls.map((c) => getShortenedMsg(c.args[0]));
-            expect(shortActualMsgs).to.deep.equal(shortExpectedMsgs);
+            if (!expectedMsgs.find((m) => m instanceof RegExpStreamingMessage)) {
+                // shortened message won't work if it's a regexp
+                const shortExpectedMsgs = expectedMsgs.map(getShortenedMsg);
+                const shortActualMsgs = calls.map((c) => getShortenedMsg(c.args[0]));
+                expect(shortActualMsgs).to.deep.equal(shortExpectedMsgs);
+            }
 
             // Next, do a more comprehensive check on the messages
             expect(calls.length).to.equal(
@@ -82,6 +86,10 @@ export class TestEventStream extends EventEmitter implements IEventStream {
         }
         Object.assign(process.env, this.originalEnv);
 
+        // Reset require cache for entryPoint files that depend on timing
+        const filePath = path.join(__dirname, 'entryPointFiles/longLoad.js');
+        delete require.cache[require.resolve(filePath)];
+
         // minor delay so that it's more likely extraneous messages are associated with this test as opposed to leaking into the next test
         await new Promise((resolve) => setTimeout(resolve, 20));
         await this.assertCalledWith();
diff --git a/test/eventHandlers/WorkerInitHandler.test.ts b/test/eventHandlers/WorkerInitHandler.test.ts
@@ -109,14 +109,28 @@ export namespace Msg {
         };
     }
 
-    export function warning(message: string): rpc.IStreamingMessage {
-        return {
-            rpcLog: {
-                message,
-                level: LogLevel.Warning,
-                logCategory: LogCategory.System,
-            },
-        };
+    export function warning(message: string | RegExp): RegExpStreamingMessage | rpc.IStreamingMessage {
+        if (typeof message === 'string') {
+            return {
+                rpcLog: {
+                    message,
+                    level: LogLevel.Warning,
+                    logCategory: LogCategory.System,
+                },
+            };
+        } else {
+            return new RegExpStreamingMessage(
+                {
+                    rpcLog: {
+                        level: LogLevel.Warning,
+                        logCategory: LogCategory.System,
+                    },
+                },
+                {
+                    'rpcLog.message': message,
+                }
+            );
+        }
     }
 
     export function error(message: string): rpc.IStreamingMessage {
@@ -321,4 +335,47 @@ describe('WorkerInitHandler', () => {
             Msg.response
         );
     });
+
+    for (const rfpValue of ['1', 'https://url']) {
+        it(`Skips warn for long load time if rfp already set to ${rfpValue}`, async () => {
+            const fileName = 'entryPointFiles/longLoad.js';
+            mockFs({
+                [__dirname]: {
+                    'package.json': JSON.stringify({ main: fileName }),
+                    entryPointFiles: mockFs.load(path.join(__dirname, 'entryPointFiles')),
+                },
+            });
+
+            process.env.WEBSITE_RUN_FROM_PACKAGE = rfpValue;
+            stream.addTestMessage(Msg.init(__dirname));
+            await stream.assertCalledWith(
+                Msg.receivedInitLog,
+                Msg.loadingEntryPoint(fileName),
+                Msg.loadedEntryPoint(fileName),
+                Msg.response
+            );
+        });
+    }
+
+    it('Warns for long load time', async () => {
+        const fileName = 'entryPointFiles/longLoad.js';
+        mockFs({
+            [__dirname]: {
+                'package.json': JSON.stringify({ main: fileName }),
+                entryPointFiles: mockFs.load(path.join(__dirname, 'entryPointFiles')),
+            },
+        });
+
+        stream.addTestMessage(Msg.init(__dirname));
+        await stream.assertCalledWith(
+            Msg.receivedInitLog,
+            Msg.loadingEntryPoint(fileName),
+            Msg.warning(/Loading "longLoad.js" took [0-9]+ms/),
+            Msg.warning(
+                'Set "WEBSITE_RUN_FROM_PACKAGE" to "1" to significantly improve load times. Learn more here: https://aka.ms/AAjon54'
+            ),
+            Msg.loadedEntryPoint(fileName),
+            Msg.response
+        );
+    });
 });
diff --git a/test/eventHandlers/entryPointFiles/longLoad.js b/test/eventHandlers/entryPointFiles/longLoad.js
@@ -0,0 +1,2 @@
+const start = Date.now();
+while (Date.now() < start + 1001) {}

Original file line number	Diff line number	Diff line change
`@@ -58,7 +58,7 @@ async function loadEntryPointFile(functionAppDirectory: string, channel: WorkerC`
`58`	`58`	`try {`
`59`	`59`	`const entryPointFilePath = path.join(functionAppDirectory, file);`
`60`	`60`	`channel.currentEntryPoint = entryPointFilePath;`
`61`		`- await loadScriptFile(entryPointFilePath, channel.packageJson);`
	`61`	`+ await loadScriptFile(channel, entryPointFilePath, channel.packageJson);`
`62`	`62`	`} finally {`
`63`	`63`	`channel.currentEntryPoint = undefined;`
`64`	`64`	`}`
Original file line number	Diff line number	Diff line change
`@@ -0,0 +1,2 @@`
	`1`	`+const start = Date.now();`
	`2`	`+while (Date.now() < start + 1001) {}`