Glimpse seems to error when application errors are thrown (but handled)

[elliotblackburn]

I just threw this into an app I'm working on to see how it goes so this isn't mission critical to me but it has meant I can't start using the package properly.

It seems Glimpse will error out when errors are thrown in the system (my app and dependencies) even if they're caught. Right now I have a piece of code which uses Bookshelf.js, I'm running the fetch command and the query is returning nothing as expected. In the bookshelf code this triggers a throw new Error line however that is then later handled by bookshelf due to a setting I have provided (require = false).

When running my application without Glimpse this is processed just fine with no problems at all, but when turning on Glimpse I get a huge stack trace which seems to begin with the line which throws the error in bookshelf, and then this line:

at Immediate.wrappedCallback (/node_modules/@glimpse/glimpse-agent-node/release/async-track/async-track.js:293:33)

(I truncated the path name to help it display better).

I've not gone too deep into the Glimpse code itself but I'm wondering if anyone has any ideas what might be going on here. I can provide more information at request but I'm not entirely sure what would be helpful with trying to track this down.

[mike-kaufman]

Thanks for reporting this @BlueHatbRit, and sorry you're having problems. Can you give us the full stack trace? Or better yet, any chance you can point us at a project where this repros?

[elliotblackburn]

Hi @mike-kaufman, I've attached a full stack trace below. It obviously includes a bunch of lines from my code so I'm going to spend some time this evening recreating it in a clean project for you guys but it might take a while.

This top level "EmptyResponse" error is thrown by Bookshelf, however it is also handled by bookshelf further down in their code. If you've not used the library before, the idea is you can pass in a flag (required = true/false), if it's true you'll get an exception back if the DB record is not found. However they will further down in their code transform this error before rejecting the promise with it.

I'll see if I can get a version going with Bookshelf and SQLite this evening if I have time, or even better if I can remove that dependency entirely. It's just their code is quite complex and might take a while to figure out exactly what's going wrong to cause the error.

{ CustomError: EmptyResponse
    at .<anonymous> (/home/vagrant/code/app/node_modules/bookshelf/lib/model.js:712:15)
    at Immediate.wrappedCallback (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/async-track/async-track.js:293:33)
    at runCallback (timers.js:637:20)
    at tryOnImmediate (timers.js:610:5)
    at processImmediate [as _immediateCallback] (timers.js:582:5)
From previous event:
    at .<anonymous> (/home/vagrant/code/app/node_modules/bookshelf/lib/model.js:705:6)
From previous event:
    at fetch (/home/vagrant/code/app/node_modules/bookshelf/lib/model.js:694:17)
    at Function.findOne (/home/vagrant/code/app/server/models/base.js:108:33)
    at Function.findOne (/home/vagrant/code/app/server/models/group.js:61:29)
    at Object.create (/home/vagrant/code/app/server/api/groups.js:35:29)
    at create (/home/vagrant/code/app/server/web-console/controllers/groups.js:38:27)
    at /home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/inspectors/util/MiddlewareWrapper.js:204:17
    at MiddlewareWrapper.wrapCommonMiddleware (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/inspectors/util/MiddlewareWrapper.js:181:13)
    at wrappedMiddleware (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/inspectors/util/MiddlewareWrapper.js:203:18)
    at Layer.handle [as handle_request] (/home/vagrant/code/app/node_modules/express/lib/router/layer.js:95:5)
    at next (/home/vagrant/code/app/node_modules/express/lib/router/route.js:131:13)
    at newNextInternal (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/inspectors/util/MiddlewareWrapper.js:178:25)
    at callbackWrapper (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/messaging/ContextManagerAsyncTrack.js:91:26)
    at AsyncTrack.runInContext (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/async-track/async-track.js:55:20)
    at wrapper (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/messaging/ContextManagerAsyncTrack.js:93:36)
    at maintainerOnly (/home/vagrant/code/app/server/middleware/web-auth.js:31:9)
    at /home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/inspectors/util/MiddlewareWrapper.js:204:17
    at MiddlewareWrapper.wrapCommonMiddleware (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/inspectors/util/MiddlewareWrapper.js:181:13)
    at wrappedMiddleware (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/inspectors/util/MiddlewareWrapper.js:203:18)
    at Layer.handle [as handle_request] (/home/vagrant/code/app/node_modules/express/lib/router/layer.js:95:5)
    at next (/home/vagrant/code/app/node_modules/express/lib/router/route.js:131:13)
    at Route.dispatch (/home/vagrant/code/app/node_modules/express/lib/router/route.js:112:3)
    at Route.dispatchRoute [as dispatch] (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/tracing/module_instrumentors/ExpressProxyActionRouteView.js:23:41)
    at Layer.handle [as handle_request] (/home/vagrant/code/app/node_modules/express/lib/router/layer.js:95:5)
    at /home/vagrant/code/app/node_modules/express/lib/router/index.js:277:22
    at Function.process_params (/home/vagrant/code/app/node_modules/express/lib/router/index.js:330:12)
    at next (/home/vagrant/code/app/node_modules/express/lib/router/index.js:271:10)
    at Function.handle (/home/vagrant/code/app/node_modules/express/lib/router/index.js:176:3)
    at router (/home/vagrant/code/app/node_modules/express/lib/router/index.js:46:12)
    at /home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/inspectors/util/MiddlewareWrapper.js:204:17
    at MiddlewareWrapper.wrapCommonMiddleware (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/inspectors/util/MiddlewareWrapper.js:181:13)
    at wrappedMiddleware (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/inspectors/util/MiddlewareWrapper.js:203:18)
    at Layer.handle [as handle_request] (/home/vagrant/code/app/node_modules/express/lib/router/layer.js:95:5) message: 'EmptyResponse' }

Is there anything else I can provide in the mean time?

[mike-kaufman]

Is there anything else I can provide in the mean time?

Thanks @BlueHatbRit, are you seeing any error messages? Or is it just that CustomError: EmptyResponse?

A slimmed-down repro would be fantastic if you can get one together.

[nikmd23]

We appreciate your help tracking down this issue @BlueHatbRit !

[elliotblackburn]

@mike-kaufman I've just realised that formatting might be from my error handler so I'll take a quick check what's popping out before that. Then I'll take a look at isolating the issue if I can.

[elliotblackburn]

@mike-kaufman I've just had a look at the raw error I'm getting come into my error handler and it's exactly what I've put above. The error message seems to be the one being thrown by Bookshelf. It's almost as if something is interrupting Bookshelf once it's thrown the error for some reason.

[mike-kaufman]

OK, I have a little bookshelf app running that repros this problem. I'll investigate what is happening & update the issue.

[elliotblackburn]

Ah fantastic, sorry I didn't get it to you first it's evening here in the UK so I've been doing it alongside other things for a few hours. Glad you can reproduce the issue, I thought for ages that I was going insane!

[avanderhoorn]

@BlueHatbRit we think we have a fix for this. With the repro we have been able to produce, it looks like BlueBird is the culprit. Specifically, for Glimpse to function we need to flow context across async boundaries, and it looks like you ran into a case we hasn't accounted for. We are currently testing our fix and should hopefully have the release out soon.

[elliotblackburn]

Hi @avanderhoorn, thanks for the update. I'm glad you guys think you've got a fix for it, do let me know if there's anything you'd like me to test on my end. Is there any rough ETA for when this fix might be released?

[davidkpiano]

@BlueHatbRit As far as I know, this is scheduled for the next release in a couple weeks (give or take).

[elliotblackburn]

@davidkpiano damn it'll miss my deadline but I'm sure it'll be useful for other projects. Thanks!

[davidkpiano]

It might be sooner! I'll have to verify with @avanderhoorn.

[mike-kaufman]

We just released v0.20.9 to npm. This build includes a fix that should prevent the behavior you're seeing. Please let us know if you discover other issues!

Thanks!

[elliotblackburn]

@mike-kaufman wonderful, thanks I'll give it a go!

[elliotblackburn]

@mike-kaufman I'm getting an error come up very frequently and I'm not sure if it's related as I'm using Bluebird as discussed above. It seems as if every HTTP request that should be logged to the console is generating one of these errors, except requests to the glimpse API.

Note: the history in the glipse UI seems to be coming through just fine.

Error

Glimpse (Error UnexpectedContextValue): Glimpse unexpected context value at location ExpressInspectorActionRouteView::onResponseEnd().  Expecting context ID e57c36c139bb11e7bb69999b84d9f358.  Actual context ID is undefined

More full log sample

This is a full log sample of me loading up a few different pages around my application. As you can see, requests to glimpse seem to be logged just fine but requests to my application aren't registering.

Glimpse (Error UnexpectedContextValue): Glimpse unexpected context value at location ExpressInspectorActionRouteView::onResponseEnd().  Expecting context ID ca544f4039bb11e7bb69999b84d9f358.  Actual context ID is undefined
Glimpse (Error UnexpectedContextValue): Glimpse unexpected context value at location ExpressInspectorActionRouteView::onResponseEnd().  Expecting context ID cece8cc139bb11e7bb69999b84d9f358.  Actual context ID is undefined
Glimpse (Error UnexpectedContextValue): Glimpse unexpected context value at location ExpressInspectorActionRouteView::onResponseEnd().  Expecting context ID cecc69e039bb11e7bb69999b84d9f358.  Actual context ID is undefined
GET /glimpse/agent/agent.js?hash={hash} 200 349.603 ms - 48786
GET /glimpse/hud/main.js?hash={hash} 200 390.478 ms - 37143
Glimpse (Error UnexpectedContextValue): Glimpse unexpected context value at location ExpressInspectorActionRouteView::onResponseEnd().  Expecting context ID cecda26139bb11e7bb69999b84d9f358.  Actual context ID is undefined
Glimpse (Error UnexpectedContextValue): Glimpse unexpected context value at location ExpressInspectorActionRouteView::onResponseEnd().  Expecting context ID cf12c1b039bb11e7bb69999b84d9f358.  Actual context ID is undefined
Glimpse (Error UnexpectedContextValue): Glimpse unexpected context value at location ExpressInspectorActionRouteView::onResponseEnd().  Expecting context ID cecfec5139bb11e7bb69999b84d9f358.  Actual context ID is undefined
POST /glimpse/message-ingress/ 202 1519.124 ms - 8
GET /glimpse/hud/assets/selawk.woff2 200 4.064 ms - 16952
POST /glimpse/message-ingress/ 202 3.439 ms - 8
POST /glimpse/message-ingress/ 202 0.692 ms - 8

I'm happy to move this into a new ticket if the cause isn't related to the original issue.

[mike-kaufman]

Thanks for reporting this @BlueHatbRit. Can you open a new issue for this? Also, if you could provide a repro that would be a great help to us.