TypeError: Cannot read property 'enter' of undefined

[emhagman]

Version: 12.13.0
Platform: Alpine 3.9 (Linux x86_64) on AWS ECS
Subsystem: domain

TypeError: Cannot read property 'enter' of undefined
    at AsyncHook.before (domain.js:76:20)
    at emitHook (internal/async_hooks.js:164:38)

We use @sentry/node to log our errors in express, which is using the domain module here:
https://github.com/getsentry/sentry-javascript/blob/master/packages/node/src/handlers.ts#L271

So far it is extremely hard to reproduce but if we run our production server for around 10 minutes, our application will crash with the above error and no other stack trace. At first, we thought it was related to #28275 but it appears to be different as it looks like the fix for this landed around 12.8.0 and we can confirm that this happens in 12.13.0 still.

Versions 12.2.0 or below do not have this issue.

I believe the actual line is 78, not 76 which can be seen here:
https://github.com/nodejs/node/blob/master/lib/domain.js#L78

EDIT: Thanks @richardlau, line 79 in v12.13.0 https://github.com/nodejs/node/blob/v12.13.0/lib/domain.js#L79

[richardlau]

In 12.13.0 the line would appear to be 79:
https://github.com/nodejs/node/blob/v12.13.0/lib/domain.js#L79

[addaleax]

@emhagman Is that all the stack trace you get? Is there any chance you could figure out what type of resource the hook is called for?

[emhagman]

@addaleax This is the only stack trace that shows up, unfortunately. I can try to add a lot more logging and get some more context around when it happens but that is about it. Can I run node with any useful DEBUG= or command-line arguments that would help you out?

[addaleax]

@emhagman Can you dump async hooks output to a file (à la https://github.com/addaleax/node/blob/ee4027d5bbabe87d4446a62ec0b7b60e7af59c30/test.js#L3-L18 except not /dev/stderr) and make sure that hook is installed and active before any code that accesses domains? That might already be very helpful.

[emhagman]

@addaleax Sure thing I'll get it to you as soon as I can. Thanks for the help!

[addaleax]

Did Github delete a comment here? Anyway; just thinking out loud…

The debug log shows that there is no destroy for the async id in question, so the C++ TLSWRAP object should still be alive, and thus keep the domain object alive through its .domain property; but the error message basically says that the domain has been garbage collected and is no longer accessible. The conclusion for me would be that the domain property on the native TLSWrap object is un-set at some point, but I really can’t think of a way that that would happen accidentally.

I’m not really sure how to best debug this further – one thing you could try is running node with --abort-on-uncaught-exception and share the core dump here, if that’s an option for you… that should at least enable verifying whether the property is set at time of the crash or not.

[emhagman]

@addaleax Sorry, I deleted the comment because I left the resource out of the logs. I was trying to get a log for you that included the resource but I currently can't make the app crash again, it really is hard to reproduce. I am doing these tests in one of our staging environments so adding --abort-on-uncaught-exception won't be a problem.

I'm not sure if it helps but we can anecdotally confirm (other users in that thread) that not using the @sentry/node middleware removes the issue. I don't know if you saw the way they're using domain and got any insight. They use it throughout the @sentry/* ecosystem for Node.

[addaleax]

@emhagman I’m not personally familiar with their code, although you can of course also report this as an issue to them if you haven’t already (and ideally add a link this one).

[emhagman]

@addaleax I have and they have deemed it an issue with Node, unfortunately. Since this has to do with GC, are there any ways to force a situation where this is more likely to occur? As of now, I have no idea how to reproduce it other than to use our app until it breaks

[addaleax]

@emhagman You could set the value of the --gc-interval=n flag to a low value, if you want to cause more frequent GC; that might help?

[emhagman]

@addaleax I have the logs with the resources. Adding --gc-interval=5 sped up the error occurring, thanks for the tip.

ASYNC_HOOK_DEBUG: init {
  id: 47259,
  type: 'TLSWRAP',
  triggerId: 47235,
  resource: ReusedHandle {
    type: 43,
    handle: TLSWrap {
      _parent: [TCP],
      _parentWrap: undefined,
      _secureContext: [SecureContext],
      reading: true,
      onhandshakestart: [Function: noop],
      onhandshakedone: [Function],
      onocspresponse: [Function: onocspresponse],
      onnewsession: [Function: onnewsessionclient],
      onkeylog: [Function: onkeylogclient],
      onerror: [Function: onerror],
      [Symbol(owner)]: [TLSSocket]
    }
  }
}

ASYNC_HOOK_DEBUG: before { id: 47259 }
TypeError: Cannot read property 'enter' of undefined
    at AsyncHook.before (domain.js:79:20)
    at emitHook (internal/async_hooks.js:164:38)
Aborted (core dumped)

Not sure if that helps. Working on getting the dump from my container now

EDIT: We use ECS Fargate on AWS so that will be impossible. I'll have to try and reproduce this locally so I can get access to the dump.

[addaleax]

@emhagman Alright, this makes a bit more sense now. The .domain property isn’t actually set on the real resource, it’s set on a fake resource object used by the HTTP agent that can be garbage collected independently.

I’m assuming that 3d9d1ad is responsible for this … any chance you could verify that the bug was introduced in Node v12.3.0?

Also, if it helps with reproducing: If i’m correct, this will mostly happen when the https.Agent re-uses sockets for multiple requests to the same host.

[emhagman]

@addaleax I believe others have already reproduced this bug in 12.3.0 and mentioned reverting to 12.2.0 fixes it in the Sentry issue thread. If I can make this happen on demand I'll be able to be positive about that.

What you said about the https agent makes perfect sense, we have a client that uses the same https agent with keepAlive on to the same host to try to save on connections to one of our internal services. That definitely helps with me getting closer to a reproducible bug. I'll keep digging, thanks again for the help.