Sentry-javascript: Request-specific context does not work with express

[asabhaney]

• [X] Review the documentation: https://docs.sentry.io/
• [X] Search for existing issues: https://github.com/getsentry/sentry-javascript/issues
• [X] Use the latest release: https://github.com/getsentry/sentry-javascript/releases

Package + Version

• [ ] @sentry/browser
• [X] @sentry/node
• [ ] raven-js
• [ ] raven-node _(raven for node)_
• [ ] other:

Version:

4.6.4

Description

I'm having a lot of issues setting request-specific context when using Sentry with Express. As a reference, I took a look at the official Express integration docs, as well as the following issue and PR:

• Docs: https://docs.sentry.io/platforms/node/express/
• Issue: https://github.com/getsentry/sentry-javascript/issues/1632
• Docs PR: https://github.com/getsentry/sentry-docs/pull/447/files (As an aside, I don't see these latest doc changes published anywhere though they were merged in)

const express = require('express')
const Sentry = require('@sentry/node')
const constants = require('./config/constants')

const api = express()

Sentry.init({
   dsn: constants.SENTRY_DSN_KEY,
   environment: constants.ENV_CURRENT
})

api.use(Sentry.Handlers.requestHandler())
api.use((req, res, next) => {
   console.log('Point A', Sentry.getHubFromCarrier(req))
   Sentry.getHubFromCarrier(req).configureScope(scope => {
      console.log('Point B')
      scope.setTag('test', 'Tag')
      scope.setExtra('test', req.path)
   })

   throw new Error('Request-specific context does not work')
})

api.use(Sentry.Handlers.errorHandler())
api.listen(constants.API_PORT)

Console Output:

Point A 
Hub {
  version: 3,
  stack: [ { client: undefined, scope: [Object] } ] }

Error: Request-specific context does not work
    at api.use (api/index.js:21:10)
    at Layer.handle [as handle_request] (api/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (api/node_modules/express/lib/router/index.js:317:13)
    at api/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (api/node_modules/express/lib/router/index.js:335:12)
    at next (api/node_modules/express/lib/router/index.js:275:10)
    at Domain.<anonymous> (api/node_modules/@sentry/node/dist/handlers.js:161:13)
    at Domain.run (domain.js:242:14)
    at sentryRequestMiddleware (api/node_modules/@sentry/node/dist/handlers.js:155:15)
    at Layer.handle [as handle_request] (api/node_modules/express/lib/router/layer.js:95:5)

Notice from the console output above:

• that Point B is never output in the console
• client in the stack of the Hub instance is undefined - not sure if this is related

Using node 8.14.0 and express 4.16.4.

[kamilogorek]

@asabhaney when using requestHandler, the hub is not attached to the request, but to the domain, as it allows us to catch async errors in context-separated manner as well.

Your code will work just fine if you replace Sentry.getHubFromCarrier(req) to Sentry.getHubFromCarrier(domain.active) instead.

(remember about const domain = require('domain') at the top).

However, getHubFromCarrier is not necessary if you are using requestHandler at all, as getCurrentHub() will detect whether there's an active domain, and read from one if so – https://github.com/getsentry/sentry-javascript/blob/f50e025b1e94699f440cd850cb463327022fde70/packages/hub/src/hub.ts#L335-L359

[avaly]

Some additional docs on the https://docs.sentry.io/platforms/node/express/ page would be great. It would stop other people going down the same rabbit hole.

[asabhaney]

I apologize for the delayed response on this. I have upgraded to @sentry/[email protected], but am still encountering issues having Sentry capture exceptions correctly for a given request, despite using getCurrentHub.

Here is my updated code:

const express = require('express')
const Sentry = require('@sentry/node')
const constants = require('./config/constants')

const api = express()

Sentry.init({
   dsn: constants.SENTRY_DSN_KEY,
   environment: constants.ENV_CURRENT,
   beforeSend(event) {
      console.log('beforeSend', event.user.id)
      return event
   }
})

api.use(Sentry.Handlers.requestHandler())
api.use(session({ ... })) // Sets req.user

// Set user for Sentry context
api.use((req, res, next) => {
   if (req.user) {
      console.log('Point A', req.user.id)
      Sentry.getCurrentHub().configureScope((scope) => {
         console.log('Point B', req.user.id)
         scope.setUser({ id: req.user.id })
      })
   }

   next()
})

// Throw an error for all requests
api.use((req, res, next) => {
   throw new Error('Uh-oh Test')
})

api.use(Sentry.Handlers.errorHandler())
api.use((err, req, res, next) => {
   const status = err.status || 500
   const msg = err.message || 'Internal Server Error'

   if (err instanceof errors.ApiError && typeof err.serialize === 'function') {
      res.status(status).json(err.serialize())
   } else {
      res.status(status).json({ name: 'API Error', message: msg })
   }
})

api.listen(constants.API_PORT)

So I fire two requests to the node server from Safari, which produces the following log output:

Point A UserOneID
Point B UserOneID
beforeSend UserOneID
Point A UserOneID
Point B UserOneID
beforeSend UserOneID

(For simplicity, I've replaced the actual req.user.id value with UserOneID)

This looks correct, including in the Sentry dashboard. Now I clear all the issues in the Sentry dashboard, then switch to Chrome, where I am logged in as a different user (represented below as UserTwoID). I fire the exact same two requests, which produces the following log output:

Point A UserTwoID // <= Correct!
Point B UserTwoID // <= Correct!
beforeSend UserOneID // <= INCORRECT! Seems to be a "ghost" from the past request
Point A UserTwoID // <= Correct!
Point B UserTwoID // <= Correct!
beforeSend UserTwoID // <= Correct!

In addition to the incorrect user being logged, when I look at the new issues that appear in the Sentry dashboard, they still show Safari as being the browser which triggered the requests (should be Chrome in this case).

Not totally sure, but it could be related to these issues:

• https://github.com/getsentry/sentry-javascript/issues/2045
• https://github.com/getsentry/sentry-javascript/issues/1773

[kamilogorek]

@asabhaney how is session exactly working? I "stubbed" it with the simple random ID and it all works fine, thus I'm not sure how to repro it.

My code: https://gist.github.com/kamilogorek/654d471ebbcab3dc20a81d7a1bfe25a7 (copy/pasted yours - constants and error sending)

Results:

Point A 674
Point B 674
beforeSend 674
Point A 134
Point B 134
beforeSend 134
Point A 730
Point B 730
beforeSend 730
Point A 967
Point B 967
beforeSend 967

[asabhaney]

Thanks for the reply @kamilogorek. Fascinating, I didn't think to question whether the session middleware might be causing the issue, but I can confirm that is in fact the culprit. Specifically, I am using express-session with connect-mongodb-session, but it seems to be the mongodb session store that's causing the issues, as the Sentry stuff all works as expected when using express-session's default in-memory store.

Interestingly, I tried a different session store library, connect-mongo, and that seems to work without any issues as well. I wanted to use connect-mongodb-session originally since it is backed by MongoDB.

I'll see if I can take a look through the connect-mongodb-session library when I get a chance to see what might be causing the issue there.

[bruun]

We had a similar issue in our code caused by the combination of express-session and passport's session middleware. I haven't had time to dig any deeper and find out what exactly passport does to mess up the scopes, but here's how we fixed it for now:

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

app.use(passport.initialize());
app.use(passport.session());

changed to

app.use(passport.initialize());
app.use(passport.session());

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

This seems to be an issue that can be caused by several middlewares. It would be nice if we could figure out what's causing the issue, and how to either prevent it or fix the other misbehaving middleware.

[kamilogorek]

I tried to use passport today to break it with no luck...

I'll close the issue for now, but please feel free to link me any working (I mean broken :D) repro-case and I'll reopen it and take a look! :)

[artdent]

I dug into this a little more, and the bug is triggered specifically by any middleware that interacts with mongodb. The mongodb connection pool loses the current process domain. That's why vanilla passport didn't repro it, but e.g. connect-mongodb-session did.

https://github.com/Automattic/mongoose/issues/4803 is an example of this behavior being reported as a bug in Mongoose. The workaround described there is to pass {domainsEnabled: true} in your mongodb options, which re-enables domain support at the cost of a performance penalty (which I have not attempted to measure).

I unfortunately haven't done the work of extracting a minimal example, but I verified these two behaviors in my own app:

• request-specific context only works if I install the Sentry middleware after my passport middleware.
• If I set {domainsEnabled: true}, then I can install the middleware in any order.