(core) Add logging of errors whenever ProxyAgent is used, and a test for it.

Summary:
Also:
- Move ProxyAgent to from app/server/utils to app/server/lib, which is
  the more usual place for such classes.
- Refactor a helper (delayAbort) that node was reporting a leak in.

Test Plan: Added a test case, and tested manually.

Reviewers: JakubSerafin

Reviewed By: JakubSerafin

Subscribers: JakubSerafin, paulfitz

Differential Revision: https://phab.getgrist.com/D3897

app/server/lib/ProxyAgent.ts

@@ -0,0 +1,26 @@
+import {HttpsProxyAgent} from "https-proxy-agent";
+import {HttpProxyAgent} from "http-proxy-agent";
+import log from 'app/server/lib/log';
+
+export function proxyAgent(requestUrl: URL): HttpProxyAgent | HttpsProxyAgent | undefined {
+  const proxy = process.env.GRIST_HTTPS_PROXY;
+  if (!proxy) {
+    return undefined;
+  }
+  const ProxyAgent = requestUrl.protocol === "https:" ? HttpsProxyAgent : HttpProxyAgent;
+  const agent = new ProxyAgent(proxy);
+
+  // Wrap the main method of ProxyAgent into a wrapper that logs errors.
+  const callback = agent.callback;
+  agent.callback = async function () {
+    try {
+      return await callback.apply(this, arguments as any);
+    } catch (e) {
+      // Include info helpful for diagnosing issues (but not the potentially sensitive full requestUrl).
+      log.rawWarn(`ProxyAgent error ${e}`,
+        {proxy, reqProtocol: requestUrl.protocol, requestOrigin: requestUrl.origin});
+      throw e;
+    }
+  };
+  return agent;
+}

app/server/lib/Requests.ts

@@ -7,7 +7,7 @@ import * as path from 'path';
 import * as tmp from 'tmp';
 import * as fse from 'fs-extra';
 import log from 'app/server/lib/log';
-import {proxyAgent} from "app/server/utils/ProxyAgent";
+import {proxyAgent} from "app/server/lib/ProxyAgent";
 import chunk = require('lodash/chunk');
 import fromPairs = require('lodash/fromPairs');
 import zipObject = require('lodash/zipObject');

app/server/lib/Triggers.ts

@@ -14,7 +14,7 @@ import {makeExceptionalDocSession} from 'app/server/lib/DocSession';
 import log from 'app/server/lib/log';
 import {matchesBaseDomain} from 'app/server/lib/requestUtils';
 import {delayAbort} from 'app/server/lib/serverUtils';
-import {proxyAgent} from 'app/server/utils/ProxyAgent';
+import {proxyAgent} from 'app/server/lib/ProxyAgent';
 import {promisifyAll} from 'bluebird';
 import * as _ from 'lodash';
 import {AbortController, AbortSignal} from 'node-abort-controller';

app/server/lib/serverUtils.ts

@@ -178,25 +178,21 @@ export function getSupportedEngineChoices(): EngineCode[]|undefined {
  * Returns a promise that resolves in the given number of milliseconds or rejects
  * when the given signal is raised.
  */
-export function delayAbort(msec: number, signal?: AbortSignal): Promise<void> {
-  return new Promise<void>((resolve, reject) => {
-    let resolved = false;
-    const timeout = setTimeout(() => {
-      if (!resolved) {
-        resolved = true;
-        resolve();
-      }
-    }, msec);
-    if (signal?.addEventListener) {
-      signal.addEventListener('abort', (ev) => {
-        if (!resolved) {
-          resolved = true;
-          clearTimeout(timeout);
-          reject(ev);
-        }
-      });
-    }
-  });
+export async function delayAbort(msec: number, signal?: AbortSignal): Promise<void> {
+  let cleanup: () => void = () => {};
+  try {
+    await new Promise<void>((resolve, reject) => {
+      const timeout = setTimeout(() => resolve(), msec);
+      signal?.addEventListener('abort', reject);
+      cleanup = () => {
+        // Be careful to clean up both the timer and the listener to avoid leaks.
+        clearTimeout(timeout);
+        signal?.removeEventListener('abort', reject);
+      };
+    });
+  } finally {
+    cleanup();
+  }
 }
 
 /**

app/server/utils/ProxyAgent.ts

@@ -1,11 +0,0 @@
-import {HttpsProxyAgent} from "https-proxy-agent";
-import {HttpProxyAgent} from "http-proxy-agent";
-
-export function proxyAgent(requestUrl: URL): HttpProxyAgent | HttpsProxyAgent | undefined {
-    const proxy = process.env.GRIST_HTTPS_PROXY;
-    if (!proxy) {
-        return undefined;
-    }
-    const ProxyAgent = requestUrl.protocol === "https:" ? HttpsProxyAgent : HttpProxyAgent;
-    return new ProxyAgent(proxy);
-}

test/server/lib/ProxyAgent.ts

@@ -1,8 +1,12 @@
-import {proxyAgent} from "app/server/utils/ProxyAgent";
+import {proxyAgent} from "app/server/lib/ProxyAgent";
+import {getAvailablePort} from "app/server/lib/serverUtils";
 import {assert} from "chai";
 import {HttpsProxyAgent} from "https-proxy-agent";
 import {HttpProxyAgent} from "http-proxy-agent";
-import {EnvironmentSnapshot} from "test/server/testUtils";
+import fetch from 'node-fetch';
+import {TestProxyServer} from 'test/server/lib/helpers/TestProxyServer';
+import {serveSomething, Serving} from 'test/server/customUtil';
+import {assertMatchArray, captureLog, EnvironmentSnapshot} from "test/server/testUtils";
 
 
 describe("ProxyAgent", function () {
@@ -35,4 +39,61 @@ describe("ProxyAgent", function () {
     const httpsProxy = proxyAgent(new URL("http://localhost:3000"));
     assert.instanceOf(httpsProxy, HttpProxyAgent);
   });
+
+  describe('proxy error handling', async function() {
+    // Handling requests
+    let serving: Serving;
+    // Proxy server emulation to test possible behaviours of real life server
+    let testProxyServer: TestProxyServer;
+
+    // Simple fetch using a proxy.
+    function testFetch(relativePath: string) {
+      const url = serving.url + relativePath;
+      return fetch(url, {
+        method: 'POST',
+        headers: {'Content-Type': 'application/json'},
+        agent: proxyAgent(new URL(url)),
+      });
+    }
+
+    beforeEach(async function () {
+      // Set up a server and a proxy.
+      const port = await getAvailablePort(22340);
+      testProxyServer = await TestProxyServer.Prepare(port);
+      serving = await serveSomething(app => {
+        app.post('/200', (_, res) => { res.sendStatus(200); res.end(); });
+        app.post('/404', (_, res) => { res.sendStatus(404); res.end(); });
+      });
+      process.env.GRIST_HTTPS_PROXY = `http://localhost:${port}`;
+    });
+
+    afterEach(async function() {
+      await serving.shutdown();
+      await testProxyServer.dispose().catch(() => {});
+    });
+
+    it("should not report error when proxy is working", async function() {
+      // Normally fetch through proxy works and produces no errors, even for failing status.
+      const logMessages1 = await captureLog('warn', async () => {
+        assert.equal((await testFetch('/200')).status, 200);
+        assert.equal((await testFetch('/404')).status, 404);
+      });
+      assert.deepEqual(logMessages1, []);
+    });
+
+    it("should report error when proxy fails", async function() {
+      // if the proxy isn't listening, fetches produces error messages.
+      await testProxyServer.dispose();
+      const logMessages2 = await captureLog('warn', async () => {
+        await assert.isRejected(testFetch('/200'), /ECONNREFUSED/);
+        await assert.isRejected(testFetch('/404'), /ECONNREFUSED/);
+      });
+
+      // We rely on "ProxyAgent error" message to detect issues with the proxy server.
+      assertMatchArray(logMessages2, [
+        /warn: ProxyAgent error.*ECONNREFUSED/,
+        /warn: ProxyAgent error.*ECONNREFUSED/,
+      ]);
+    });
+  });
 });