diff --git a/src/LegacyFunctionLoader.ts b/src/LegacyFunctionLoader.ts index 449561ae..97021dfd 100644 --- 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; + load( + channel: WorkerChannel, + functionId: string, + metadata: rpc.IRpcFunctionMetadata, + packageJson: PackageJson + ): Promise; 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 { + async load( + channel: WorkerChannel, + functionId: string, + metadata: rpc.IRpcFunctionMetadata, + packageJson: PackageJson + ): Promise { 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 = (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 index 8eb33f26..7538be91 100644 --- 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 index 52b5dcc7..5f7ce3de 100644 --- 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 { - 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 { + 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 index 8075a49d..9b0320b2 100644 --- 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 index a3efdabf..cdca02ef 100644 --- 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 = (sinon.createStubInstance(WorkerChannel)); beforeEach(() => { loader = new LegacyFunctionLoader(); @@ -32,6 +35,7 @@ describe('LegacyFunctionLoader', () => { mock('test', {}); await expect( loader.load( + channel, 'functionId', { scriptFile: 'test', @@ -46,6 +50,7 @@ describe('LegacyFunctionLoader', () => { it('does not load proxy function', async () => { mock('test', {}); await loader.load( + channel, 'functionId', { isProxy: true, @@ -61,6 +66,7 @@ describe('LegacyFunctionLoader', () => { const entryPoint = 'wrongEntryPoint'; await expect( loader.load( + channel, 'functionId', { scriptFile: 'test', @@ -78,6 +84,7 @@ describe('LegacyFunctionLoader', () => { const entryPoint = 'test'; await expect( loader.load( + channel, 'functionId', { scriptFile: 'test', @@ -109,6 +116,7 @@ describe('LegacyFunctionLoader', () => { mock('test', new FuncObject()); await loader.load( + channel, 'functionId', { scriptFile: 'test', @@ -127,6 +135,7 @@ describe('LegacyFunctionLoader', () => { mock('test', { test: async () => {} }); await loader.load( + channel, 'functionId', { scriptFile: 'test', @@ -146,6 +155,7 @@ describe('LegacyFunctionLoader', () => { mock('test', { test: async () => {} }); await loader.load( + channel, 'functionId', { scriptFile: 'test', diff --git a/test/eventHandlers/FunctionLoadHandler.test.ts b/test/eventHandlers/FunctionLoadHandler.test.ts index c1abb872..7d85bc65 100644 --- 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>().throws(err); + loader.load = sinon + .stub<[WorkerChannel, string, rpc.IRpcFunctionMetadata, PackageJson], Promise>() + .throws(err); stream.addTestMessage({ requestId: 'id', diff --git a/test/eventHandlers/TestEventStream.ts b/test/eventHandlers/TestEventStream.ts index e1e1d84e..4fe9f5e5 100644 --- 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 index 4c119f14..6917f803 100644 --- 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 new file mode 100644 index 00000000..d39311ae --- /dev/null +++ b/test/eventHandlers/entryPointFiles/longLoad.js @@ -0,0 +1,2 @@ +const start = Date.now(); +while (Date.now() < start + 1001) {} \ No newline at end of file