From be5cb9124a5d1fec8c2ed6dff5cdbf786fac2991 Mon Sep 17 00:00:00 2001 From: Dmitry S Date: Wed, 17 May 2023 09:59:35 -0400 Subject: [PATCH] (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 | 26 ++++++++++++++ app/server/lib/Requests.ts | 2 +- app/server/lib/Triggers.ts | 2 +- app/server/lib/serverUtils.ts | 34 ++++++++---------- app/server/utils/ProxyAgent.ts | 11 ------ test/server/lib/ProxyAgent.ts | 65 ++++++++++++++++++++++++++++++++-- 6 files changed, 106 insertions(+), 34 deletions(-) create mode 100644 app/server/lib/ProxyAgent.ts delete mode 100644 app/server/utils/ProxyAgent.ts diff --git a/app/server/lib/ProxyAgent.ts b/app/server/lib/ProxyAgent.ts new file mode 100644 index 00000000..e587cf15 --- /dev/null +++ b/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; +} diff --git a/app/server/lib/Requests.ts b/app/server/lib/Requests.ts index 6d0a4a0d..4cee6a2e 100644 --- a/app/server/lib/Requests.ts +++ b/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'); diff --git a/app/server/lib/Triggers.ts b/app/server/lib/Triggers.ts index 5551ba2c..de554e57 100644 --- a/app/server/lib/Triggers.ts +++ b/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'; diff --git a/app/server/lib/serverUtils.ts b/app/server/lib/serverUtils.ts index 0bd3400c..7c01a1d2 100644 --- a/app/server/lib/serverUtils.ts +++ b/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 { - return new Promise((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 { + let cleanup: () => void = () => {}; + try { + await new Promise((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(); + } } /** diff --git a/app/server/utils/ProxyAgent.ts b/app/server/utils/ProxyAgent.ts deleted file mode 100644 index ac3128be..00000000 --- a/app/server/utils/ProxyAgent.ts +++ /dev/null @@ -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); -} diff --git a/test/server/lib/ProxyAgent.ts b/test/server/lib/ProxyAgent.ts index 2d1df607..e168ab47 100644 --- a/test/server/lib/ProxyAgent.ts +++ b/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/, + ]); + }); + }); });