Node: AsyncLocalStorage: Cannot read property 'Symbol(kResourceStore)'

Created on 29 Jul 2020  路  8Comments  路  Source: nodejs/node
  • 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:
https://github.com/nodejs/node/blob/13c5a1629cd025ba560f34f6d3190b2f38d184d4/lib/async_hooks.js#L219

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

async_hooks confirmed-bug
Source
picture johanneswuerbach
👍1

Most helpful comment

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.

picture Flarna on 31 Jul 2020
👍2

All 8 comments

Looking into the changelog I see only https://github.com/nodejs/node/pull/34319 in this area.

fyi @nodejs/async_hooks

Flarna picture Flarna on 30 Jul 2020
👍1

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

puzpuzpuz picture puzpuzpuz on 30 Jul 2020

I鈥檓 also wondering if this reproduces without @opentelemetry/plugin-http?

addaleax picture addaleax on 30 Jul 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?

Flarna picture Flarna on 31 Jul 2020

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

I鈥檓 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)
johanneswuerbach picture johanneswuerbach on 31 Jul 2020
👍2

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 picture Flarna on 31 Jul 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.

Flarna picture Flarna on 31 Jul 2020
👍2

Sigh. Thanks for figuring this out, @flarna :) https://github.com/nodejs/node/pull/34573 should address this.

addaleax picture addaleax on 31 Jul 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

sandeepks1 picture sandeepks1  路  3Comments
ksushilmaurya picture ksushilmaurya  路  3Comments
vsemozhetbyt picture vsemozhetbyt  路  3Comments
Icemic picture Icemic  路  3Comments
danialkhansari picture danialkhansari  路  3Comments