Tweak lstat bug retry logic (#712)

Author: ejizba

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<unknown> {
     // 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;
                 }
             },
         }

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<void> {
         // 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);
     });

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

test/eventHandlers/testApp/.gitignore

@@ -1 +1,2 @@
-package.json
+package.json
+src/temp.js

test/eventHandlers/testApp/src/throwLstatError.js

@@ -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');