From e01abd6b680b0072459ecb19166d8c63d4c86d93 Mon Sep 17 00:00:00 2001 From: Eric Jizba Date: Thu, 17 Aug 2023 14:17:35 -0700 Subject: [PATCH] Tweak lstat bug retry logic (#712) --- src/loadScriptFile.ts | 19 +++++++---- .../eventHandlers/FunctionLoadHandler.test.ts | 34 +++++++++++++------ test/eventHandlers/TestEventStream.ts | 6 +++- test/eventHandlers/testApp/.gitignore | 3 +- .../testApp/src/throwLstatError.js | 1 - test/eventHandlers/testAppUtils.ts | 1 + 6 files changed, 43 insertions(+), 21 deletions(-) delete mode 100644 test/eventHandlers/testApp/src/throwLstatError.js diff --git a/src/loadScriptFile.ts b/src/loadScriptFile.ts index dd80937..b598f8f 100644 --- a/src/loadScriptFile.ts +++ b/src/loadScriptFile.ts @@ -11,34 +11,39 @@ import { PackageJson } from './parsers/parsePackageJson'; import LogCategory = rpc.RpcLog.RpcLogCategory; import LogLevel = rpc.RpcLog.Level; +let hasLoggedAttempt = 0; +let hasLoggedWarning = false; + export async function loadScriptFile(filePath: string, packageJson: PackageJson): Promise { // See the following issue for more details on why we want to retry // https://github.com/Azure/azure-functions-nodejs-worker/issues/693 - const fileName = path.basename(filePath); + const retries = 9; return await retry( async (currentAttempt: number) => { - if (currentAttempt > 1) { + if (currentAttempt > 1 && currentAttempt > hasLoggedAttempt) { worker.log({ - message: `Retrying load of file "${fileName}". Attempt ${currentAttempt}/${10}`, + message: `Retrying file load. Attempt ${currentAttempt}/${retries + 1}`, level: LogLevel.Debug, logCategory: LogCategory.System, }); + hasLoggedAttempt = currentAttempt; } return loadScriptFileInternal(filePath, packageJson); }, { - retries: 9, - minTimeout: 50, + retries: retries, + minTimeout: 500, onFailedAttempt: (error) => { if (!/lstat.*home/i.test(error?.message || '')) { // this will abort the retries if it's an error we don't recognize throw error; - } else if (error.retriesLeft > 0) { + } else if (error.retriesLeft > 0 && !hasLoggedWarning) { worker.log({ - message: `Warning: Failed to load file "${fileName}" with error "${error.message}"`, + message: `Warning: Failed to load file with error "${error.message}"`, level: LogLevel.Warning, logCategory: LogCategory.System, }); + hasLoggedWarning = true; } }, } diff --git a/test/eventHandlers/FunctionLoadHandler.test.ts b/test/eventHandlers/FunctionLoadHandler.test.ts index a57ba77..d7a1570 100644 --- a/test/eventHandlers/FunctionLoadHandler.test.ts +++ b/test/eventHandlers/FunctionLoadHandler.test.ts @@ -2,7 +2,9 @@ // Licensed under the MIT License. import { expect } from 'chai'; +import * as fs from 'fs/promises'; import 'mocha'; +import * as path from 'path'; import { AzureFunctionsRpcMessages as rpc } from '../../azure-functions-language-worker-protobuf/src/rpc'; import { getLegacyFunction } from '../../src/LegacyFunctionLoader'; import { worker } from '../../src/WorkerContext'; @@ -11,6 +13,7 @@ import { nonNullValue } from '../../src/utils/nonNull'; import { RegExpStreamingMessage, TestEventStream } from './TestEventStream'; import { beforeEventHandlerSuite } from './beforeEventHandlerSuite'; import { msg } from './msg'; +import { tempFile, testAppSrcPath } from './testAppUtils'; describe('FunctionLoadHandler', () => { let stream: TestEventStream; @@ -44,22 +47,31 @@ describe('FunctionLoadHandler', () => { it('handles transient lstat function load exception', async function (this: Mocha.ITestCallbackContext): Promise { // https://github.com/Azure/azure-functions-nodejs-worker/issues/693 - this.timeout(40 * 1000); + this.timeout(15 * 1000); - stream.addTestMessage(msg.funcLoad.request('throwLstatError.js')); + await fs.writeFile( + path.join(testAppSrcPath, tempFile), + `if (Date.now() < ${Date.now() + 5 * 1000}) + { + throw new Error("UNKNOWN: unknown error, lstat 'D:\\\\home'"); + } else { + module.exports = async () => { } + }` + ); + + stream.addTestMessage(msg.funcLoad.request(tempFile)); const errorMessage = "UNKNOWN: unknown error, lstat 'D:\\home'"; - const msgs: (rpc.IStreamingMessage | RegExpStreamingMessage)[] = [msg.funcLoad.receivedRequestLog]; - for (let i = 2; i <= 10; i++) { - msgs.push( - msg.warningLog(`Warning: Failed to load file "throwLstatError.js" with error "${errorMessage}"`), - msg.debugLog(`Retrying load of file "throwLstatError.js". Attempt ${i}/10`) - ); + const msgs: (rpc.IStreamingMessage | RegExpStreamingMessage)[] = [ + msg.funcLoad.receivedRequestLog, + msg.warningLog(`Warning: Failed to load file with error "${errorMessage}"`), + ]; + for (let i = 2; i <= 5; i++) { + msgs.push(msg.debugLog(`Retrying file load. Attempt ${i}/10`)); } - const message = `Worker was unable to load function testFuncName: '${errorMessage}'`; - msgs.push(msg.errorLog(message), msg.funcLoad.failedResponse(message)); + msgs.push(msg.funcLoad.response); - await delay(30 * 1000); + await delay(8 * 1000); await stream.assertCalledWith(...msgs); }); diff --git a/test/eventHandlers/TestEventStream.ts b/test/eventHandlers/TestEventStream.ts index 5c19ba7..9d91dce 100644 --- a/test/eventHandlers/TestEventStream.ts +++ b/test/eventHandlers/TestEventStream.ts @@ -45,8 +45,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 - if (!expectedMsgs.find((m) => m instanceof RegExpStreamingMessage)) { + if ( + !expectedMsgs.find((m) => m instanceof RegExpStreamingMessage) || + calls.length !== expectedMsgs.length + ) { // shortened message won't work if it's a regexp + // but if the call count doesn't match, this error will be better than the one below const shortExpectedMsgs = expectedMsgs.map(getShortenedMsg); const shortActualMsgs = calls.map((c) => getShortenedMsg(c.args[0])); expect(shortActualMsgs).to.deep.equal(shortExpectedMsgs); diff --git a/test/eventHandlers/testApp/.gitignore b/test/eventHandlers/testApp/.gitignore index 2ff8622..a71e00f 100644 --- a/test/eventHandlers/testApp/.gitignore +++ b/test/eventHandlers/testApp/.gitignore @@ -1 +1,2 @@ -package.json \ No newline at end of file +package.json +src/temp.js \ No newline at end of file diff --git a/test/eventHandlers/testApp/src/throwLstatError.js b/test/eventHandlers/testApp/src/throwLstatError.js deleted file mode 100644 index e64ce9a..0000000 --- a/test/eventHandlers/testApp/src/throwLstatError.js +++ /dev/null @@ -1 +0,0 @@ -throw new Error("UNKNOWN: unknown error, lstat 'D:\\home'"); \ No newline at end of file diff --git a/test/eventHandlers/testAppUtils.ts b/test/eventHandlers/testAppUtils.ts index 83b5a91..0dbf4f8 100644 --- a/test/eventHandlers/testAppUtils.ts +++ b/test/eventHandlers/testAppUtils.ts @@ -4,6 +4,7 @@ import * as fs from 'fs/promises'; import * as path from 'path'; +export const tempFile = 'temp.js'; export const testAppPath = path.join(__dirname, 'testApp'); export const testAppSrcPath = path.join(testAppPath, 'src'); export const testPackageJsonPath = path.join(testAppPath, 'package.json');