using ctx.throw results in both `request errored` and `request completed` being logged

[jstewmon]

If a request promise is rejected, koa-pino-logger will log a request errored message, then pino-http will log a request completed message.

Consider this app:

const Koa = require('koa');
const logger = require('koa-pino-logger');

const app = new Koa();
app.use(logger());
app.use((ctx, next) => {
  ctx.throw(401);
});
app.listen(3000);

Here's the output:

 ✗ node demo.js | jq
{
  "level": 50,
  "time": 1554318378433,
  "msg": "request errored",
  "pid": 70644,
  "hostname": "jstewmon-mbp",
  "req": {
    "id": 1,
    "method": "GET",
    "url": "/",
    "headers": {
      "host": "localhost:3000",
      "user-agent": "curl/7.54.0",
      "accept": "*/*"
    },
    "remoteAddress": "::1",
    "remotePort": 57345
  },
  "res": {
    "statusCode": 404,
    "headers": {}
  },
  "err": {
    "type": "UnauthorizedError",
    "message": "Unauthorized",
    "stack": "UnauthorizedError: Unauthorized\n    at Object.throw (/Users/jstewmon/scratch/node_modules/koa/lib/context.js:97:11)\n    at app.use (/Users/jstewmon/scratch/demo.js:7:12)\n    at dispatch (/Users/jstewmon/scratch/node_modules/koa-compose/index.js:42:32)\n    at pino (/Users/jstewmon/scratch/node_modules/koa-pino-logger/logger.js:12:12)\n    at dispatch (/Users/jstewmon/scratch/node_modules/koa-compose/index.js:42:32)\n    at /Users/jstewmon/scratch/node_modules/koa-compose/index.js:34:12\n    at Application.handleRequest (/Users/jstewmon/scratch/node_modules/koa/lib/application.js:151:12)\n    at Server.handleRequest (/Users/jstewmon/scratch/node_modules/koa/lib/application.js:133:19)\n    at Server.emit (events.js:182:13)\n    at parserOnIncoming (_http_server.js:672:12)"
  },
  "v": 1
}
{
  "level": 30,
  "time": 1554318378439,
  "msg": "request completed",
  "pid": 70644,
  "hostname": "jstewmon-mbp",
  "req": {
    "id": 1,
    "method": "GET",
    "url": "/",
    "headers": {
      "host": "localhost:3000",
      "user-agent": "curl/7.54.0",
      "accept": "*/*"
    },
    "remoteAddress": "::1",
    "remotePort": 57345
  },
  "res": {
    "statusCode": 401,
    "headers": {
      "content-type": "text/plain; charset=utf-8",
      "content-length": "12"
    }
  },
  "responseTime": 8,
  "v": 1
}

These are the oddities I see:

1. res.statusCode in the request errored message is inaccurate b/c the Koa Context error handler has not yet run
2. Generating two messages instead of one for the request is not ideal IMO

From studying onResFinished in pino-http, it looks like koa-pino-logger should set res.err and make res.status a proxy for res.statusCode instead calling ctx.log.error.

I noticed that koa-pino-logger depends on outdated versions of pino-http and koa, so I suppose there is an opportunity to update those deps and make the koa-pino-logger experience more congruent with pino-http.

[manast-apsis]

yes, this is definitely annoying, level 50 usually trigger alarms and stuff. Is there any workaround for this?