Repository: solid/community-server (ts)

Issue:
Stream warnings on every call 
I just noticed when doing a simple call such as `curl http://localhost:3000/` on the server a logger warning gets printed:

```
[StreamUtil] warn: Piped stream errored with premature close
```

Not sure yet when this started happening but we probably don't want that.

Pull request:
fix: Prevent warnings for expected errors
Closes #842.

Not exactly the most stable solution but it does solve the problem.

Patch:
diff --git a/src/util/StreamUtil.ts b/src/util/StreamUtil.ts
index 6c59d2770..1affe13b8 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);
       }


Test patch:
diff --git a/test/integration/GuardedStream.test.ts b/test/integration/GuardedStream.test.ts
index 8ba32961e..6e84edb42 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 be3e0b1d6..ba9c0fafa 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();