server: downgrade ECANCELED logs to debug (#9615)

Backports PR #9612

**Commit 1:**
server: downgrade ECANCELED logs to debug

Just like we do for EPIPE and ECONNRESET, we can downgrade ECANCELED
client errors to the debug logging level rather than treating them as
errors.

* Original sha: c2c2bbe42c
* Authored by Court Ewing <court@epixa.com> on 2016-12-22T18:41:04Z

src/server/logging/__tests__/log_interceptor.js

@@ -17,6 +17,7 @@ function stubClientErrorEvent(errno) {
 
 const stubEconnresetEvent = () => stubClientErrorEvent('ECONNRESET');
 const stubEpipeEvent = () => stubClientErrorEvent('EPIPE');
+const stubEcanceledEvent = () => stubClientErrorEvent('ECANCELED');
 
 function assertDowngraded(transformed) {
   expect(!!transformed).to.be(true);
@@ -33,12 +34,6 @@ describe('server logging LogInterceptor', () => {
       assertDowngraded(interceptor.downgradeIfEconnreset(event));
     });
 
-    it('transforms EPIPE events', () => {
-      const interceptor = new LogInterceptor();
-      const event = stubEpipeEvent();
-      assertDowngraded(interceptor.downgradeIfEpipe(event));
-    });
-
     it('does not match if the tags are not in order', () => {
       const interceptor = new LogInterceptor();
       const event = stubEconnresetEvent();
@@ -59,4 +54,60 @@ describe('server logging LogInterceptor', () => {
       expect(interceptor.downgradeIfEconnreset(event)).to.be(null);
     });
   });
+
+  describe('#downgradeIfEpipe()', () => {
+    it('transforms EPIPE events', () => {
+      const interceptor = new LogInterceptor();
+      const event = stubEpipeEvent();
+      assertDowngraded(interceptor.downgradeIfEpipe(event));
+    });
+
+    it('does not match if the tags are not in order', () => {
+      const interceptor = new LogInterceptor();
+      const event = stubEpipeEvent();
+      event.tags = [...event.tags.slice(1), event.tags[0]];
+      expect(interceptor.downgradeIfEpipe(event)).to.be(null);
+    });
+
+    it('ignores non EPIPE events', () => {
+      const interceptor = new LogInterceptor();
+      const event = stubClientErrorEvent('not EPIPE');
+      expect(interceptor.downgradeIfEpipe(event)).to.be(null);
+    });
+
+    it('ignores if tags are wrong', () => {
+      const interceptor = new LogInterceptor();
+      const event = stubEpipeEvent();
+      event.tags = ['different', 'tags'];
+      expect(interceptor.downgradeIfEpipe(event)).to.be(null);
+    });
+  });
+
+  describe('#downgradeIfEcanceled()', () => {
+    it('transforms ECANCELED events', () => {
+      const interceptor = new LogInterceptor();
+      const event = stubEcanceledEvent();
+      assertDowngraded(interceptor.downgradeIfEcanceled(event));
+    });
+
+    it('does not match if the tags are not in order', () => {
+      const interceptor = new LogInterceptor();
+      const event = stubEcanceledEvent();
+      event.tags = [...event.tags.slice(1), event.tags[0]];
+      expect(interceptor.downgradeIfEcanceled(event)).to.be(null);
+    });
+
+    it('ignores non ECANCELED events', () => {
+      const interceptor = new LogInterceptor();
+      const event = stubClientErrorEvent('not ECANCELED');
+      expect(interceptor.downgradeIfEcanceled(event)).to.be(null);
+    });
+
+    it('ignores if tags are wrong', () => {
+      const interceptor = new LogInterceptor();
+      const event = stubEcanceledEvent();
+      event.tags = ['different', 'tags'];
+      expect(interceptor.downgradeIfEcanceled(event)).to.be(null);
+    });
+  });
 });

src/server/logging/log_interceptor.js

@@ -63,8 +63,35 @@ export class LogInterceptor extends Stream.Transform {
     };
   }
 
+  /**
+   *  Since the upgrade to hapi 14, any socket write
+   *  error is surfaced as a generic "client error"
+   *  but "ECANCELED" specifically is not useful for the
+   *  logs unless you are trying to debug edge-case behaviors.
+   *
+   *  For that reason, we downgrade this from error to debug level
+   *
+   *  @param {object} - log event
+   */
+  downgradeIfEcanceled(event) {
+    const isClientError = doTagsMatch(event, ['connection', 'client', 'error']);
+    const isEcanceled = isClientError && get(event, 'data.errno') === 'ECANCELED';
+
+    if (!isEcanceled) return null;
+
+    return {
+      event: 'log',
+      pid: event.pid,
+      timestamp: event.timestamp,
+      tags: ['debug', 'connection', 'ecanceled'],
+      data: 'ECANCELED: Socket was closed by the client (probably the browser) before the response could be completed'
+    };
+  }
+
   _transform(event, enc, next) {
-    const downgraded = this.downgradeIfEconnreset(event) || this.downgradeIfEpipe(event);
+    const downgraded = this.downgradeIfEconnreset(event)
+      || this.downgradeIfEpipe(event)
+      || this.downgradeIfEcanceled(event);
 
     this.push(downgraded || event);
     next();