Tweak Koa request logging (#294)

- Limit request logging to errors - Remove `err` boilerplate that is now handled by Koala
seek-oss · Dec 13, 2020 · 9002d51 · 9002d51
1 parent 805b951
commit 9002d51
Show file tree

Hide file tree

Showing 4 changed files with 27 additions and 51 deletions.
diff --git a/.changeset/large-melons-shout.md b/.changeset/large-melons-shout.md
@@ -0,0 +1,5 @@
+---
+'skuba': patch
+---
+
+**template/koa-rest-api:** Limit request logging to errors
diff --git a/template/koa-rest-api/package.json b/template/koa-rest-api/package.json
@@ -1,30 +1,30 @@
 {
   "dependencies": {
     "@koa/router": "^10.0.0",
-    "@seek/logger": "^4.4.4",
+    "@seek/logger": "^4.4.5",
     "skuba-dive": "^1.1.1",
-    "hot-shots": "^8.2.0",
+    "hot-shots": "^8.2.1",
     "koa": "^2.13.0",
     "koa-bodyparser": "^4.3.0",
     "koa-compose": "^4.2.0",
     "runtypes": "^5.0.1",
-    "runtypes-filter": "^0.4.0",
+    "runtypes-filter": "^0.4.2",
     "seek-datadog-custom-metrics": "^4.0.0",
-    "seek-koala": "^5.0.0",
-    "uuid": "^8.3.1"
+    "seek-koala": "^5.1.0",
+    "uuid": "^8.3.2"
   },
   "devDependencies": {
-    "@types/chance": "^1.1.0",
+    "@types/chance": "^1.1.1",
     "@types/koa": "^2.11.6",
     "@types/koa-bodyparser": "^5.0.2",
     "@types/koa__router": "^8.0.3",
-    "@types/node": "^14.14.0",
+    "@types/node": "^14.14.13",
     "@types/supertest": "^2.0.10",
     "@types/uuid": "^8.3.0",
     "chance": "^1.1.7",
     "pino-pretty": "^4.3.0",
     "skuba": "*",
-    "supertest": "^6.0.0"
+    "supertest": "^6.0.1"
   },
   "engines": {
     "node": ">=12"

diff --git a/template/koa-rest-api/src/framework/server.test.ts b/template/koa-rest-api/src/framework/server.test.ts
@@ -31,13 +31,7 @@ describe('createApp', () => {
 
     expect(rootLogger.error).not.toBeCalled();
 
-    expect(rootLogger.info).toBeCalledTimes(1);
-
-    expect(rootLogger.info).nthCalledWith(
-      1,
-      expect.objectContaining({ status: 200 }),
-      'request',
-    );
+    expect(rootLogger.info).not.toBeCalled();
 
     metricsClient.expectTagSubset(['env:test', 'version:test']);
     metricsClient.expectTagSubset([
@@ -59,13 +53,7 @@ describe('createApp', () => {
 
     expect(rootLogger.error).not.toBeCalled();
 
-    expect(rootLogger.info).toBeCalledTimes(1);
-
-    expect(rootLogger.info).nthCalledWith(
-      1,
-      expect.objectContaining({ status: 200 }),
-      'request',
-    );
+    expect(rootLogger.info).not.toBeCalled();
 
     metricsClient.expectTagSubset([
       'http_method:put',
@@ -86,13 +74,7 @@ describe('createApp', () => {
 
     expect(rootLogger.error).not.toBeCalled();
 
-    expect(rootLogger.info).toBeCalledTimes(1);
-
-    expect(rootLogger.info).nthCalledWith(
-      1,
-      expect.objectContaining({ status: 404 }),
-      'request',
-    );
+    expect(rootLogger.info).not.toBeCalled();
 
     metricsClient.expectTagSubset([
       'http_method:get',
@@ -115,12 +97,10 @@ describe('createApp', () => {
 
     expect(rootLogger.error).not.toBeCalled();
 
-    expect(rootLogger.info).toBeCalledTimes(1);
-
     expect(rootLogger.info).nthCalledWith(
       1,
       expect.objectContaining({ err: expect.any(Error), status: 400 }),
-      'request',
+      'Client error',
     );
 
     metricsClient.expectTagSubset([
@@ -142,12 +122,10 @@ describe('createApp', () => {
       .expect('server', /.+/)
       .expect('x-api-version', /.+/);
 
-    expect(rootLogger.error).toBeCalledTimes(1);
-
     expect(rootLogger.error).nthCalledWith(
       1,
       expect.objectContaining({ err: expect.any(Error), status: 500 }),
-      'request',
+      'Server error',
     );
 
     expect(rootLogger.info).not.toBeCalled();
@@ -173,12 +151,10 @@ describe('createApp', () => {
       .expect('server', /.+/)
       .expect('x-api-version', /.+/);
 
-    expect(rootLogger.error).toBeCalledTimes(1);
-
     expect(rootLogger.error).nthCalledWith(
       1,
       expect.objectContaining({ err, status: 500 }),
-      'request',
+      'Server error',
     );
 
     expect(rootLogger.info).not.toBeCalled();
@@ -203,12 +179,10 @@ describe('createApp', () => {
       .expect('server', /.+/)
       .expect('x-api-version', /.+/);
 
-    expect(rootLogger.error).toBeCalledTimes(1);
-
     expect(rootLogger.error).nthCalledWith(
       1,
       expect.objectContaining({ err: null, status: 500 }),
-      'request',
+      'Server error',
     );
 
     expect(rootLogger.info).not.toBeCalled();
@@ -234,12 +208,10 @@ describe('createApp', () => {
       .expect('server', /.+/)
       .expect('x-api-version', /.+/);
 
-    expect(rootLogger.error).toBeCalledTimes(1);
-
     expect(rootLogger.error).nthCalledWith(
       1,
       expect.objectContaining({ err, status: 500 }),
-      'request',
+      'Server error',
     );
 
     expect(rootLogger.info).not.toBeCalled();

diff --git a/template/koa-rest-api/src/framework/server.ts b/template/koa-rest-api/src/framework/server.ts
@@ -20,15 +20,14 @@ const metrics = MetricsMiddleware.create(
 
 const requestLogging = RequestLogging.createMiddleware<DefaultState, Context>(
   (ctx, fields, err) => {
-    /* istanbul ignore next: error handler should catch `err` first */
-    const data = {
-      ...fields,
-      err: err ?? ErrorMiddleware.thrown(ctx),
-    };
+    if (typeof err === 'undefined') {
+      // Depend on sidecar logging for happy path requests
+      return;
+    }
 
     return ctx.status < 500
-      ? rootLogger.info(data, 'request')
-      : rootLogger.error(data, 'request');
+      ? rootLogger.info(fields, 'Client error')
+      : rootLogger.error(fields, 'Server error');
   },
 );