From 5f8ec5dd15661872328f0919bcd43529266b9d7f Mon Sep 17 00:00:00 2001
From: Joachim Van Herwegen <joachimvh@gmail.com>
Date: Wed, 28 Jul 2021 16:29:28 +0200
Subject: [PATCH] fix: Prevent warnings for expected errors

---
 src/util/StreamUtil.ts                 | 13 +++++++++++-
 test/integration/GuardedStream.test.ts |  3 ++-
 test/unit/util/StreamUtil.test.ts      | 28 +++++++++++++++++++++++++-
 3 files changed, 41 insertions(+), 3 deletions(-)

diff --git a/src/util/StreamUtil.ts b/src/util/StreamUtil.ts
index 6c59d27704..1affe13b8c 100644
--- a/src/util/StreamUtil.ts
+++ b/src/util/StreamUtil.ts
@@ -23,6 +23,15 @@ export async function readableToString(stream: Readable): Promise<string> {
   return (await arrayifyStream(stream)).join('');
 }
 
+// These error messages usually indicate expected behaviour so should not give a warning.
+// We compare against the error message instead of the code
+// since the second one is from an external library that does not assign an error code.
+// At the time of writing the first one gets thrown in Node 16 and the second one in Node 14.
+const safeErrors = new Set([
+  'Cannot call write after a stream was destroyed',
+  'premature close',
+]);
+
 /**
  * Pipes one stream into another and emits errors of the first stream with the second.
  * In case of an error in the first stream the second one will be destroyed with the given error.
@@ -53,7 +62,9 @@ export function pipeSafely<T extends Writable>(readable: NodeJS.ReadableStream,
     // In case the input readable is guarded, it will no longer log errors since `pump` attaches a new error listener
     pump(readable, destination, (error): void => {
       if (error) {
-        logger.warn(`Piped stream errored with ${error.message}`);
+        const msg = `Piped stream errored with ${error.message}`;
+        logger.log(safeErrors.has(error.message) ? 'debug' : 'warn', msg);
+
         // Make sure the final error can be handled in a normal streaming fashion
         destination.emit('error', mapError ? mapError(error) : error);
       }
diff --git a/test/integration/GuardedStream.test.ts b/test/integration/GuardedStream.test.ts
index 8ba32961eb..6e84edb424 100644
--- a/test/integration/GuardedStream.test.ts
+++ b/test/integration/GuardedStream.test.ts
@@ -14,7 +14,8 @@ import type { Representation,
   Logger } from '../../src';
 
 jest.mock('../../src/logging/LogUtil', (): any => {
-  const logger: Logger = { error: jest.fn(), debug: jest.fn(), warn: jest.fn(), info: jest.fn() } as any;
+  const logger: Logger =
+    { error: jest.fn(), debug: jest.fn(), warn: jest.fn(), info: jest.fn(), log: jest.fn() } as any;
   return { getLoggerFor: (): Logger => logger };
 });
 const logger: jest.Mocked<Logger> = getLoggerFor('GuardedStream') as any;
diff --git a/test/unit/util/StreamUtil.test.ts b/test/unit/util/StreamUtil.test.ts
index be3e0b1d69..ba9c0fafa5 100644
--- a/test/unit/util/StreamUtil.test.ts
+++ b/test/unit/util/StreamUtil.test.ts
@@ -1,9 +1,17 @@
 import { PassThrough } from 'stream';
 import arrayifyStream from 'arrayify-stream';
 import streamifyArray from 'streamify-array';
+import type { Logger } from '../../../src/logging/Logger';
+import { getLoggerFor } from '../../../src/logging/LogUtil';
 import { isHttpRequest } from '../../../src/server/HttpRequest';
 import { guardedStreamFrom, pipeSafely, transformSafely, readableToString } from '../../../src/util/StreamUtil';
 
+jest.mock('../../../src/logging/LogUtil', (): any => {
+  const logger: Logger = { warn: jest.fn(), log: jest.fn() } as any;
+  return { getLoggerFor: (): Logger => logger };
+});
+const logger: jest.Mocked<Logger> = getLoggerFor('StreamUtil') as any;
+
 jest.mock('../../../src/server/HttpRequest', (): any => ({
   isHttpRequest: jest.fn(),
 }));
@@ -18,7 +26,7 @@ describe('StreamUtil', (): void => {
 
   describe('#pipeSafely', (): void => {
     beforeEach(async(): Promise<void> => {
-      (isHttpRequest as unknown as jest.Mock).mockClear();
+      jest.clearAllMocks();
     });
 
     it('pipes data from one stream to the other.', async(): Promise<void> => {
@@ -37,6 +45,8 @@ describe('StreamUtil', (): void => {
       const output = new PassThrough();
       const piped = pipeSafely(input, output);
       await expect(readableToString(piped)).rejects.toThrow('error');
+      expect(logger.log).toHaveBeenCalledTimes(1);
+      expect(logger.log).toHaveBeenLastCalledWith('warn', 'Piped stream errored with error');
     });
 
     it('supports mapping errors to something else.', async(): Promise<void> => {
@@ -50,6 +60,22 @@ describe('StreamUtil', (): void => {
       await expect(readableToString(piped)).rejects.toThrow('other error');
     });
 
+    it('logs specific safer errors as debug.', async(): Promise<void> => {
+      const input = streamifyArray([ 'data' ]);
+      input.read = (): any => {
+        input.emit('error', new Error('Cannot call write after a stream was destroyed'));
+        return null;
+      };
+      const output = new PassThrough();
+      const piped = pipeSafely(input, output);
+      await expect(readableToString(piped)).rejects.toThrow('Cannot call write after a stream was destroyed');
+      expect(logger.log).toHaveBeenCalledTimes(1);
+      expect(logger.log).toHaveBeenLastCalledWith(
+        'debug',
+        'Piped stream errored with Cannot call write after a stream was destroyed',
+      );
+    });
+
     it('destroys the source stream in case the destinations becomes unpiped.', async(): Promise<void> => {
       const input = new PassThrough();
       const output = new PassThrough();