TypeError: Cannot read property 'enter' of undefined

@richardlau

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

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

@emhagman

@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?

@addaleax

@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?

@emhagman

@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.

@addaleax

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

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.

@addaleax

@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.

@emhagman

@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).

@addaleax

@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

@emhagman

@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?

@addaleax

@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.

@emhagman

@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.

@addaleax

@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.

@emhagman

@emhagman If you’re in a position to try out patches to Node.js, could you try this one?

diff --git a/lib/_http_agent.js b/lib/_http_agent.js
index dcb5ed376de8..f4d9bb7fe36a 100644
--- a/lib/_http_agent.js
+++ b/lib/_http_agent.js
@@ -44,10 +44,15 @@ const {
 // ClientRequest.onSocket(). The Agent is now *strictly*
 // concerned with managing a connection pool.
 
+const kReusedHandle = Symbol('kReusedHandle');
+
 class ReusedHandle {
   constructor(type, handle) {
     this.type = type;
     this.handle = handle;
+    // Tie the lifetime of the two objects together, mostly for the 'domain'
+    // module.
+    handle[kReusedHandle] = this;
   }
 }

@emhagman

Alright! Put together a fix and a regression test: #30196

@emhagman Thanks for the bug report and working this out with me!

@addaleax

@addaleax Thanks so much 💯 I appreciate you taking the time to look into and fix it. Your test code is very helpful in learning how to debug/reproduce things like this in the future. Thanks!

EDIT: Any idea on how long this will take to get cut into a release for 12.X?

@emhagman

EDIT: Any idea on how long this will take to get cut into a release for 12.X?

@emhagman So, typically the way this works is that the PR takes at least 48 hours to land unless explicitly being fast-tracked (I don’t think this qualifies as a trivial change), plus the time to the next Current/13.x release (Tuesday according to nodejs/Release#487); and then the LTS rules says that commits need to have been released two weeks before being backported into LTS, but if there’s a strong case for doing so sooner, that’s usually not an issue for a low-risk patch like this one.

@addaleax

@addaleax Got it, thanks 👍

@addaleax

Awesome job @addaleax, thank you! :)

http,async_hooks: keep resource object alive from socket

We still see the issue with node:12.14.1 (and above), @sentry/node and express

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

We still see this issue.

I don't understand enough about the node garbage collection, but this does not seem to work.

Keeping a strong reference myself to the domain makes the problem go away:

const pairing = new Map()

asyncHooks.createHook({
  init(id) {
    if (process.domain !== null && process.domain !== undefined) {
      pairing.set(id, process.domain)
    }
  },
  destroy(asyncId) {
    pairing.delete(asyncId)
  }
}).enable()

I am also still seeing this issue. However I cannot always reproduce this result. Maybe it is a race condition or something? It occurs here: https://github.com/nodejs/node/blob/v14.18.1/lib/domain.js#L97

TypeError: Cannot read property 'enter' of undefined
    at AsyncHook.before (domain.js:97:20)
    at emitHook (internal/async_hooks.js:235:38)
    at emitBeforeScript (internal/async_hooks.js:501:5)
    at promiseBeforeHook (internal/async_hooks.js:345:3)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)

We ran into this in node 16 in our CI the other day:

https://github.com/getsentry/sentry-javascript/pull/4061/checks?check_run_id=3954472061#step:6:688

Specifically, it was in 16.12.0. Couldn't repro it locally, and restarting the job a few times fixed it, so agree that it's flaky.

Can confirm that this or something like it remains in play. Same stack trace as those newer reports above, under both v17.1.0 and v16.13.0:

TypeError: Cannot read properties of undefined (reading 'enter')
    at AsyncHook.before (node:domain:97:20)
    at emitHook (node:internal/async_hooks:237:38)
    at emitBeforeScript (node:internal/async_hooks:505:5)
    at promiseBeforeHook (node:internal/async_hooks:347:3)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)

However, running the same script under v12.22.7 does work as expected. I can very reliably reproduce the problem on newer node versions, so that's something.

I suppose I should open a new issue entirely......?

Navigation Menu

Repository navigation

TypeError: Cannot read property 'enter' of undefined #30122

19 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

TypeError: Cannot read property 'enter' of undefined #30122

Description

Activity

richardlau commented on Oct 25, 2019

addaleax commented on Oct 25, 2019

emhagman commented on Oct 26, 2019

addaleax commented on Oct 26, 2019

emhagman commented on Oct 26, 2019

addaleax commented on Oct 26, 2019

emhagman commented on Oct 26, 2019

addaleax commented on Oct 26, 2019

emhagman commented on Oct 26, 2019

addaleax commented on Oct 26, 2019

emhagman commented on Oct 26, 2019

addaleax commented on Oct 26, 2019

emhagman commented on Oct 26, 2019

addaleax commented on Oct 26, 2019

19 remaining items

addaleax commented on Oct 31, 2019

emhagman commented on Oct 31, 2019

addaleax commented on Oct 31, 2019

emhagman commented on Nov 1, 2019

kamilogorek commented on Nov 7, 2019

derom commented on Feb 21, 2020

pelzerim commented on Jun 16, 2021

Langstra commented on Oct 22, 2021

lobsterkatie commented on Oct 22, 2021

cemerick commented on Nov 28, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions