Sentry-javascript: Morgan and @sentry/node with the Express Handler not working well together

Created on 26 Jan 2019  Â·  13Comments  Â·  Source: getsentry/sentry-javascript

Package + Version

  • [x] @sentry/node

Version:

4.5.3

Description

When using the morgan logging middleware, alongside app.use(Sentry.Handlers.errorHandler() as express.ErrorRequestHandler), whenever there is an async controller that throws an Error, no futher requests can be made, and the following stack trace is shown:

GET /api/grin/stats 500 54.544 ms - -
Error: connect ECONNREFUSED 35.202.26.92:8080
    at Object._errnoException (util.js:1022:11)
    at _exceptionWithHostPort (util.js:1044:20)
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1198:14)
TypeError: this.app.get is not a function
    at IncomingMessage.ip (/Users/eddiewang/js/src/github.com/LuxorLabs/luxor-mining-v3/node_modules/express/lib/request.js:350:24)
    at getip (/Users/eddiewang/js/src/github.com/LuxorLabs/luxor-mining-v3/node_modules/morgan/index.js:466:14)
    at logger (/Users/eddiewang/js/src/github.com/LuxorLabs/luxor-mining-v3/node_modules/morgan/index.js:107:26)
    at Layer.handle [as handle_request] (/Users/eddiewang/js/src/github.com/LuxorLabs/luxor-mining-v3/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/Users/eddiewang/js/src/github.com/LuxorLabs/luxor-mining-v3/node_modules/express/lib/router/index.js:317:13)
    at /Users/eddiewang/js/src/github.com/LuxorLabs/luxor-mining-v3/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/Users/eddiewang/js/src/github.com/LuxorLabs/luxor-mining-v3/node_modules/express/lib/router/index.js:335:12)
    at next (/Users/eddiewang/js/src/github.com/LuxorLabs/luxor-mining-v3/node_modules/express/lib/router/index.js:275:10)
    at jsonParser (/Users/eddiewang/js/src/github.com/LuxorLabs/luxor-mining-v3/node_modules/body-parser/lib/types/json.js:110:7)
    at Layer.handle [as handle_request] (/Users/eddiewang/js/src/github.com/LuxorLabs/luxor-mining-v3/node_modules/express/lib/router/layer.js:95:5)

This does not happen if I comment out app.use(morgan('dev')), or if I comment out app.use(Sentry.Handlers.errorHandler() as express.ErrorRequestHandler)... I just can't use both at the same time, and I'd like to do that.

Appreciate any guidance here.

Most helpful comment

Seeing the same thing with bunyan (2.0.2) and express-bunyan-logger (1.3.2). Downgrading to 4.5.0 fixes it.

All 13 comments

We are experiencing weird things after updating from 4.5.0 -> 4.5.3, the context is different from the OP's but the underlying this.app.get error is the same.

@rstims does downgrading to 4.5.0 fix the issue?

@eddiewang yeah it looks like 4.5.0 works as expected

Seeing the same thing with bunyan (2.0.2) and express-bunyan-logger (1.3.2). Downgrading to 4.5.0 fixes it.

Also seeing this. https://github.com/getsentry/sentry-javascript/issues/1859 looks like the same issue

Same issue with Feathers and Winston
https://github.com/feathersjs/feathers/issues/1183

I'm not using anything like Winston or Morgan, but I'm also experiencing this issue.

Related bits:

Sentry.init({
  beforeSend(event, hint) {
    const {
      originalException,
    } = hint

    const {
      message,
    } = originalException

    if (message.match(/NotAuthenticated/i)) {
      return null
    }

    return event
  },
  dsn: env.SENTRY_DSN,
})

// ...

app.use(Sentry.Handlers.requestHandler())

// ...
app.use((error, request, response, next) => {
  if (!error.stack.match(/NotAuthenticated/i)) {
    err(error.stack)
  }

  next(error)
})
app.use(Sentry.Handlers.errorHandler())
app.use(express.errorHandler())

Will check if downgrading fixes the issue.

Fixed in 4.5.4 – https://github.com/getsentry/sentry-javascript/releases/tag/4.5.4
Sorry for the inconvenience :)

The issue still exists in "@sentry/node": "^4.6.2" using as Express middleware

TypeError: req.emit is not a function at Socket.socketOnTimeout (_http_server.js:427:48) at Socket.emit (events.js:197:13) at Socket.EventEmitter.emit (domain.js:446:20) at Socket._onTimeout (net.js:447:8) at listOnTimeout (timers.js:327:15) at processTimers (timers.js:271:5)

Really?... can you provide a repro please? Every scenario I tested worked just fine.

I think sentry tries to attach something to res object asynchronously, but the connection is already closed which crashes the api.

const api = express();
sentry.init({ dsn: process.env.SENTRY, environment: process.env.DOMAIN });
api.use(sentry.Handlers.requestHandler());
....
api.use(sentry.Handlers.errorHandler());
api.use((err, req, res, next) => {
    let { message, statusCode } = err;
    if (err.name === 'UnauthorizedError') {
        statusCode = 401;
        message = 'Token is invalid.';
    }
    res.status(statusCode || 400).json({ error: message });
});

Works just fine with your repro ¯_(ツ)_/¯

image

not sure, that was the logic before we removed it. Might be something related to our own controllers.

Was this page helpful?
0 / 5 - 0 ratings