Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
jstewmon opened this issue Apr 3, 2019 · 1 comment · May be fixed by #20
Open

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

jstewmon opened this issue Apr 3, 2019 · 1 comment · May be fixed by #20

Comments

@jstewmon
Copy link

jstewmon commented Apr 3, 2019

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.
@jstewmon jstewmon linked a pull request Apr 3, 2019 that will close this issue
Open
@manast-apsis
Copy link

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

interop with pino-http by setting res.err instead of calling log.error jstewmon/koa-pino-logger
2 participants
@jstewmon @manast-apsis