Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

AsyncLocalStorage: Cannot read property 'Symbol(kResourceStore)' #34556

Closed
johanneswuerbach opened this issue Jul 29, 2020 · 10 comments
Closed
Assignees
Labels
async_hooks Issues and PRs related to the async hooks subsystem. confirmed-bug Issues with confirmed bugs.

Comments

@johanneswuerbach
Copy link

  • Version: v14.6.0 (works on v14.5.0)
  • Platform: Unix
  • Subsystem: async_hooks

What steps will reproduce the bug?

I'm not entirely sure yet, but will continue investigating. Any pointers would be appreciated.

Sadly the code itself is private, but I'll try to extract a reproduction.

How often does it reproduce? Is there a required condition?

I only see this crash reliably on every test run on one of our services, all the others seem to work fine.

The service works on v14.4.0 and v14.5.0, so this seems to be a regression introduced in v14.6.0.

What is the expected behavior?

Working AsyncLocalStorage.

What do you see instead?

An exception

TypeError: Cannot read property 'Symbol(kResourceStore)' of undefined
    at AsyncLocalStorage._propagate (async_hooks.js:246:34)
    at AsyncHook.init (async_hooks.js:222:22)
    at emitInitNative (internal/async_hooks.js:198:43)
    at emitInitScript (internal/async_hooks.js:466:3)
    at initAsyncResource (internal/timers.js:155:5)
    at new Timeout (internal/timers.js:188:3)
    at setUnrefTimeout (internal/timers.js:370:17)
    at cache (internal/http.js:27:3)
    at utcDate (internal/http.js:19:18)
    at ServerResponse._storeHeader (_http_outgoing.js:391:26)
    at ServerResponse.writeHead (_http_server.js:313:8)
    at ServerResponse._implicitHeader (_http_server.js:240:8)
    at write_ (_http_outgoing.js:663:9)
    at ServerResponse.end (_http_outgoing.js:776:5)
    at /app/node_modules/@opentelemetry/plugin-http/build/src/http.js:213:87
    at HttpPlugin._safeExecute (/app/node_modules/@opentelemetry/plugin-http/build/src/http.js:303:20)
    at ServerResponse.response.end (/app/node_modules/@opentelemetry/plugin-http/build/src/http.js:213:49)

Likely the result of executionAsyncResource() returning undefined here:

const currentResource = executionAsyncResource();

Additional information

AsyncLocalStorage is used using https://github.com/open-telemetry/opentelemetry-js/tree/v0.10.1 and via the AsyncLocalStorageContextManager https://github.com/open-telemetry/opentelemetry-js/blob/v0.10.1/packages/opentelemetry-context-async-hooks/src/AsyncLocalStorageContextManager.ts

@Flarna
Copy link
Member

Flarna commented Jul 30, 2020

Looking into the changelog I see only #34319 in this area.

fyi @nodejs/async_hooks

@Flarna Flarna added the async_hooks Issues and PRs related to the async hooks subsystem. label Jul 30, 2020
@puzpuzpuz
Copy link
Member

@johanneswuerbach that sounds like a executionAsyncResource() bug. It would be great if you could provide a reproducer.

@addaleax
Copy link
Member

I’m also wondering if this reproduces without @opentelemetry/plugin-http?

@Flarna
Copy link
Member

Flarna commented Jul 30, 2020

@johanneswuerbach A reproducer would be really great. It would also helpful to see the complete stack. Maybe you could set Error.stackTraceLimit to a higher?

@johanneswuerbach
Copy link
Author

I'll try to come up with a repro, but couldn't.

I’m also wondering if this reproduces without @opentelemetry/plugin-http?

We use other services with the same plugin, so that alone seems not to be the issue.

@Flarna here is the full trace (xxx is private code):

TypeError: Cannot read property 'Symbol(kResourceStore)' of undefined
    at AsyncLocalStorage._propagate (async_hooks.js:246:34)
    at AsyncHook.init (async_hooks.js:222:22)
    at emitInitNative (internal/async_hooks.js:198:43)
    at emitInitScript (internal/async_hooks.js:466:3)
    at initAsyncResource (internal/timers.js:155:5)
    at new Timeout (internal/timers.js:188:3)
    at setUnrefTimeout (internal/timers.js:370:17)
    at cache (internal/http.js:27:3)
    at utcDate (internal/http.js:19:18)
    at ServerResponse._storeHeader (_http_outgoing.js:391:26)
    at ServerResponse.writeHead (_http_server.js:313:8)
    at ServerResponse._implicitHeader (_http_server.js:240:8)
    at write_ (_http_outgoing.js:663:9)
    at ServerResponse.end (_http_outgoing.js:776:5)
    at /app/node_modules/@opentelemetry/plugin-http/build/src/http.js:213:87
    at HttpPlugin._safeExecute (/app/node_modules/@opentelemetry/plugin-http/build/src/http.js:303:20)
    at ServerResponse.response.end (/app/node_modules/@opentelemetry/plugin-http/build/src/http.js:213:49)
    at ServerResponse.send (/app/node_modules/express/lib/response.js:221:10)
    at ServerResponse.res.httpify (/xxx:101:21)
    at ServerResponse.res.error (/xxx:41:13)
    at /xxx:126:13
    at Layer.handle_error (/app/node_modules/express/lib/router/layer.js:71:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:315:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at Layer.handle_error (/app/node_modules/express/lib/router/layer.js:67:12)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:315:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at Layer.handle_error (/app/node_modules/express/lib/router/layer.js:67:12)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:315:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at Layer.handle_error (/app/node_modules/express/lib/router/layer.js:67:12)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:315:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at Layer.handle_error (/app/node_modules/express/lib/router/layer.js:67:12)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:315:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at Layer.handle_error (/app/node_modules/express/lib/router/layer.js:67:12)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:315:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at Layer.handle_error (/app/node_modules/express/lib/router/layer.js:67:12)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:315:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at param (/app/node_modules/express/lib/router/index.js:354:14)
    at param (/app/node_modules/express/lib/router/index.js:365:14)
    at Function.process_params (/app/node_modules/express/lib/router/index.js:410:3)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at Layer.handle_error (/app/node_modules/express/lib/router/layer.js:67:12)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:315:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at Layer.handle_error (/app/node_modules/express/lib/router/layer.js:67:12)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:315:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at Layer.handle_error (/app/node_modules/express/lib/router/layer.js:67:12)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:315:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:97:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at /xxx:21:5
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at /xxx.js:34:5
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at /xxx:5:9
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at /xxx:9:9
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at /xxx:43:9
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at format (/xxx)
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at /xxx:107:9
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at /xxx:50:9
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at /xxx:30:9
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at /xxx:72:9
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at middleware (/xxx:105:13)
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at expressInit (/app/node_modules/express/lib/middleware/init.js:40:5)
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at /app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:55
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at contextWrapper (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AbstractAsyncHooksContextManager.js:40:32)
    at arguments.<computed> (/app/node_modules/@opentelemetry/plugin-express/build/src/express.js:150:62)
    at query (/app/node_modules/express/lib/middleware/query.js:45:5)
    at /app/node_modules/@opentelemetry/plugin-express/build/src/express.js:153:41
    at Layer.handle [as handle_request] (/app/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/app/node_modules/express/lib/router/index.js:317:13)
    at /app/node_modules/express/lib/router/index.js:284:7
    at Function.process_params (/app/node_modules/express/lib/router/index.js:335:12)
    at next (/app/node_modules/express/lib/router/index.js:275:10)
    at Function.handle (/app/node_modules/express/lib/router/index.js:174:3)
    at Function.handle (/app/node_modules/express/lib/application.js:174:10)
    at Server.app (/app/node_modules/express/lib/express.js:39:9)
    at Server.emit (events.js:314:20)
    at /app/node_modules/@opentelemetry/plugin-http/build/src/http.js:224:69
    at HttpPlugin._safeExecute (/app/node_modules/@opentelemetry/plugin-http/build/src/http.js:303:20)
    at /app/node_modules/@opentelemetry/plugin-http/build/src/http.js:224:35
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at ContextAPI.with (/app/node_modules/@opentelemetry/node/node_modules/@opentelemetry/api/build/src/api/context.js:59:46)
    at Tracer.withSpan (/app/node_modules/@opentelemetry/node/node_modules/@opentelemetry/tracing/build/src/Tracer.js:91:32)
    at /app/node_modules/@opentelemetry/plugin-http/build/src/http.js:198:39
    at async_hooks.js:266:14
    at AsyncResource.runInAsyncScope (async_hooks.js:189:9)
    at AsyncLocalStorage.run (async_hooks.js:264:21)
    at AsyncLocalStorageContextManager.with (/app/node_modules/@opentelemetry/context-async-hooks/build/src/AsyncLocalStorageContextManager.js:32:40)
    at ContextAPI.with (/app/node_modules/@opentelemetry/plugin-http/node_modules/@opentelemetry/api/build/src/api/context.js:59:46)
    at Server.incomingRequest (/app/node_modules/@opentelemetry/plugin-http/build/src/http.js:196:38)
    at parserOnIncoming (_http_server.js:781:12)
    at HTTPParser.parserOnHeadersComplete (_http_common.js:119:17)

@Flarna
Copy link
Member

Flarna commented Jul 30, 2020

Thanks, that helped to get a reproducer:

const { AsyncLocalStorage } = require("async_hooks");
const al = new AsyncLocalStorage();

function run(cnt) {
    if (cnt !== 0) return al.run({}, run, --cnt)
    console.log("done");
}
run(16) // 15 works...

@Flarna
Copy link
Member

Flarna commented Jul 31, 2020

Seems the managed and native stack get out of sync.
Once the limit of 16 for the async_id stack is reached JS pushAsyncContext forwards to native pushAsyncContext_ but there is nothing put into native_execution_async_resources_ if push_async_context is called from JS as it assumes the managed part has it's own stack but that's not true.
At this time native_execution_async_resources_ contains only the root context.

Next call to executionAsyncResource() doesn't find something on JS stack but in native we look at offset 17 of native_execution_async_resources_ which is empty.

I will not find any time during the next few day to continue with this so anyone feel free to pick it up.

@addaleax addaleax self-assigned this Jul 31, 2020
@addaleax
Copy link
Member

Sigh. Thanks for figuring this out, @Flarna :) #34573 should address this.

addaleax added a commit to addaleax/node that referenced this issue Jul 31, 2020
460c81d introduced a bug where the execution resource was not
stored properly if we needed to call into C++ to extend the stack size.
Fix that bug by always storing the resource.

Refs: nodejs#34319
Fixes: nodejs#34556
@puzpuzpuz puzpuzpuz added the confirmed-bug Issues with confirmed bugs. label Jul 31, 2020
Flarna added a commit to dynatrace-oss-contrib/node that referenced this issue Aug 4, 2020
Inspired by the callstack at nodejs#34556 (comment)

If the wanted store is equal to the active store it's not needed to
create an AsyncResource.

Refs: nodejs#34556 (comment)
codebytere pushed a commit that referenced this issue Aug 5, 2020
460c81d introduced a bug where the execution resource was not
stored properly if we needed to call into C++ to extend the stack size.
Fix that bug by always storing the resource.

Refs: #34319
Fixes: #34556

PR-URL: #34573
Reviewed-By: Andrey Pechkurov <[email protected]>
Reviewed-By: Benjamin Gruenbaum <[email protected]>
Reviewed-By: Gerhard Stöbich <[email protected]>
Reviewed-By: Gus Caplan <[email protected]>
Flarna added a commit that referenced this issue Aug 6, 2020
Inspired by the callstack at #34556 (comment)

If the wanted store is equal to the active store it's not needed to
create an AsyncResource.

Refs: #34556 (comment)

PR-URL: #34616
Reviewed-By: Anna Henningsen <[email protected]>
Reviewed-By: Stephen Belanger <[email protected]>
Reviewed-By: Vladimir de Turckheim <[email protected]>
Reviewed-By: Andrey Pechkurov <[email protected]>
addaleax pushed a commit that referenced this issue Aug 8, 2020
Inspired by the callstack at #34556 (comment)

If the wanted store is equal to the active store it's not needed to
create an AsyncResource.

Refs: #34556 (comment)

PR-URL: #34616
Reviewed-By: Anna Henningsen <[email protected]>
Reviewed-By: Stephen Belanger <[email protected]>
Reviewed-By: Vladimir de Turckheim <[email protected]>
Reviewed-By: Andrey Pechkurov <[email protected]>
codebytere pushed a commit that referenced this issue Aug 11, 2020
460c81d introduced a bug where the execution resource was not
stored properly if we needed to call into C++ to extend the stack size.
Fix that bug by always storing the resource.

Refs: #34319
Fixes: #34556

PR-URL: #34573
Reviewed-By: Andrey Pechkurov <[email protected]>
Reviewed-By: Benjamin Gruenbaum <[email protected]>
Reviewed-By: Gerhard Stöbich <[email protected]>
Reviewed-By: Gus Caplan <[email protected]>
codebytere pushed a commit that referenced this issue Aug 11, 2020
Inspired by the callstack at #34556 (comment)

If the wanted store is equal to the active store it's not needed to
create an AsyncResource.

Refs: #34556 (comment)

PR-URL: #34616
Reviewed-By: Anna Henningsen <[email protected]>
Reviewed-By: Stephen Belanger <[email protected]>
Reviewed-By: Vladimir de Turckheim <[email protected]>
Reviewed-By: Andrey Pechkurov <[email protected]>
addaleax added a commit that referenced this issue Sep 22, 2020
460c81d introduced a bug where the execution resource was not
stored properly if we needed to call into C++ to extend the stack size.
Fix that bug by always storing the resource.

Refs: #34319
Fixes: #34556

PR-URL: #34573
Reviewed-By: Andrey Pechkurov <[email protected]>
Reviewed-By: Benjamin Gruenbaum <[email protected]>
Reviewed-By: Gerhard Stöbich <[email protected]>
Reviewed-By: Gus Caplan <[email protected]>
addaleax added a commit that referenced this issue Sep 22, 2020
460c81d introduced a bug where the execution resource was not
stored properly if we needed to call into C++ to extend the stack size.
Fix that bug by always storing the resource.

Refs: #34319
Fixes: #34556

PR-URL: #34573
Reviewed-By: Andrey Pechkurov <[email protected]>
Reviewed-By: Benjamin Gruenbaum <[email protected]>
Reviewed-By: Gerhard Stöbich <[email protected]>
Reviewed-By: Gus Caplan <[email protected]>
addaleax pushed a commit that referenced this issue Sep 22, 2020
Inspired by the callstack at #34556 (comment)

If the wanted store is equal to the active store it's not needed to
create an AsyncResource.

Refs: #34556 (comment)

PR-URL: #34616
Reviewed-By: Anna Henningsen <[email protected]>
Reviewed-By: Stephen Belanger <[email protected]>
Reviewed-By: Vladimir de Turckheim <[email protected]>
Reviewed-By: Andrey Pechkurov <[email protected]>
@andrewzenkovT
Copy link

Is fix in v14.21.3?

@anyu
Copy link

anyu commented Mar 18, 2024

Also getting this error for v14.20.0

abhishekumar-tyagi pushed a commit to abhishekumar-tyagi/node that referenced this issue May 5, 2024
460c81d introduced a bug where the execution resource was not
stored properly if we needed to call into C++ to extend the stack size.
Fix that bug by always storing the resource.

Refs: nodejs/node#34319
Fixes: nodejs/node#34556

PR-URL: nodejs/node#34573
Reviewed-By: Andrey Pechkurov <[email protected]>
Reviewed-By: Benjamin Gruenbaum <[email protected]>
Reviewed-By: Gerhard Stöbich <[email protected]>
Reviewed-By: Gus Caplan <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
async_hooks Issues and PRs related to the async hooks subsystem. confirmed-bug Issues with confirmed bugs.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

6 participants