UnexpectedContextValue Errors when using "redis"

[elliotblackburn]

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

Further details

This may be linked to the usage of Bluebird as described in #97 as it seems to be talking about the context. I'm using glimpse in a project with Bookshelf and Bluebird (npm modules) which kicked up a fuss in that last issue. However this may of course be completely unrelated.

I'll spend tomorrow morning trying to come up with a small repo to recreate the issue.

[mike-kaufman]

Thanks @BlueHatbRit. Let me know if you get a repro case.

[mike-kaufman]

Hey @BlueHatbRit , wondering if you can try something out for me. We have a new build on our "alpha feed". It's early & hasn't been fully tested, but it has a change that may solve your errors.

To try it out, you'll need to do the following:

npm config set @glimpse:registry=https://www.myget.org/F/g-alpha/npm/
npm install @glimpse/glimpse
npm ls @glimpse/glimpse # ----> this should show @glimpse/[email protected]

After the above, start your app with the following comand-line params:

node your-app.js --glimpse.contextmanager zones

or

npm run start -- --glimpse.contextmanager zones

Let me know if you're able to try above out on your app, and if have a better experience here.

[elliotblackburn]

Hi @mike-kaufman, sorry I've not been able to whip you up a repository which displays the issue. I'm in some final deadlines at university and I'm totally slammed.

I'll give this a go for you now and let you know how it goes!

[elliotblackburn]

@mike-kaufman I followed through the steps and managed to install 0.21.1 just fine, when starting up with:

node index.js --glimpse.contextmanager zones

I got the following stack trace when hitting my index page.

/home/vagrant/code/app/node_modules/zone.js/dist/zone-node.js:185
                        throw error;
                        ^

TypeError: Cannot read property 'hudScriptTemplate' of undefined
    at ScriptManager.hudScript (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/messaging/ScriptMan
ager.js:59:42)
    at ScriptManager.getScriptTagsForCurrentRequest (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/releas
e/messaging/ScriptManager.js:69:38)
    at ServerResponse.glimpseHttpProxyEnd (/home/vagrant/code/app/node_modules/@glimpse/glimpse-agent-node/release/inspecto
rs/HttpProxy.js:352:54)
    at writeend (/home/vagrant/code/app/node_modules/express-session/index.js:261:22)
    at onsave (/home/vagrant/code/app/node_modules/express-session/index.js:335:11)
    at Command.callback (/home/vagrant/code/app/node_modules/connect-redis/lib/connect-redis.js:201:10)
    at normal_reply (/home/vagrant/code/app/node_modules/redis/index.js:721:21)
    at RedisClient.return_reply (/home/vagrant/code/app/node_modules/redis/index.js:819:9)
    at JavascriptRedisParser.returnReply (/home/vagrant/code/app/node_modules/redis/index.js:192:18)
    at JavascriptRedisParser.execute (/home/vagrant/code/app/node_modules/redis-parser/lib/parser.js:574:12)
    at Socket.<anonymous> (/home/vagrant/code/app/node_modules/redis/index.js:274:27)
    at ZoneDelegate.invokeTask (/home/vagrant/code/app/node_modules/zone.js/dist/zone-node.js:414:31)
    at Zone.runTask (/home/vagrant/code/app/node_modules/zone.js/dist/zone-node.js:181:47)
    at Socket.ZoneTask.invoke (/home/vagrant/code/app/node_modules/zone.js/dist/zone-node.js:476:38)
    at emitOne (events.js:96:13)
    at Socket.emit (events.js:188:7)

Now this seems to be something completely different coming from my express session handlers but the line causing an issue is zone.js which I'm assuming is to do with the contextmanager that was injected perhaps?

[mike-kaufman]

Great, thanks @BlueHatbRit . Do you still see those UnexpectedContextValue errors? Or did they all disappear?

/cc @philliphoff - FYI if this look familiar at all wrt hud/script injection?

[elliotblackburn]

@mike-kaufman I can't get that far as requesting any endpoint crashes the application before glimpse reports anything.

[elliotblackburn]

I'd be happy to provide you guys access to my project with a Vagrant environment if that would be useful to you.

[mike-kaufman]

I'd be happy to provide you guys access to my project with a Vagrant environment if that would be useful to you.

This would be great! You can send mail to {first}.{last}@microsoft.com. Thanks!!!

[elliotblackburn]

@mike-kaufman I've added you to both repos and sent a full email which should get you going really quickly.

[mike-kaufman]

@BlueHatbRit - thanks! Looking into this now.

[japrescott]

I am on the latest node and latest express versions and am getting this problem as well, but not only for onResponseEnd but also for onResponseSend.
But: I am using cluster to start multiple child processes. Because I am using socket.io and a client always needs to talk to the same worker, I am also using sticky-sessions (https://socket.io/docs/using-multiple-nodes/) -> https://github.com/indutny/sticky-session.
As this "hack" requires the master to listen to 80 and forwards the message to a worker on a random port ( -> app.listens(0, localhost) ) I am sure this is the cause for the issue

[mike-kaufman]

@BlueHatbRit - We think we've got your lost context issues fixed. We should have a release up on npm late next week, or you can try out the latest build on our alpha feed:

npm config set @glimpse:registry=https://www.myget.org/F/g-alpha/npm/
npm install @glimpse/glimpse
npm ls @glimpse/glimpse # ----> this should show @glimpse/[email protected]

Then launch your app normally:

node index.js

Let us know if you have any more lost context errors.

[mike-kaufman]

@japrescott - it's quite possible that your lost context errors are a different root cause than those reported by @BlueHatbRit. I've opened #114 to track the issue you reported.

What's happening here is we need to track state across async code transitions, which means we need to effectively proxy these continuation points in lots of different client libraries. We likely need to correctly proxy socket.io and/or sticky sessions.

[elliotblackburn]

@mike-kaufman I'll give this a go now and report back.

[elliotblackburn]

@mike-kaufman these issues seem to be resolved now using 0.21.3 from the alpha channel. Thanks for all your work, I'll close the issue.

[nikmd23]

Hi @BlueHatbRit

We'd love to have a chat with you about how you're using Glimpse, what's useful and what isn't. It shouldn't take more than 30 mins and there's no need to prepare in advance. If you're interested, just pick a time slot over at https://calendly.com/nikmd23/30min

Thanks!

[elliotblackburn]

Hi @nikmd23, I'd love to but I'm afraid I'm heading to Hong Kong for a week tomorrow and won't be around until about the Friday after I get back. Am I able to pick a slot just after then?

[nikmd23]

Of course! Enjoy your trip and we'll chat later.