Node: CLS store gets reset on the first callback in http scenario

Created on 3 Mar 2020 · 7Comments · Source: nodejs/node

Version: master
Platform: Linux
Subsystem: async_hooks

What steps will reproduce the bug?

I have been trying to write some new scenarios for AsyncLocalStorage class, as mentioned in https://github.com/nodejs/node/issues/31978, and came across this issue:

const { AsyncLocalStorage } = require('async_hooks');
const http = require('http')
const cls = new AsyncLocalStorage();

const server = http.createServer((req, res) => {
  res.write('hello')
  setTimeout(() => {
    res.end(' world!')
  }, 1000)
})

server.listen(12000, () => {
  cls.run(() => {
    const req = http.get('http://localhost:12000', (res) => {
      const store = cls.getStore()
      store.set('foo', '')
      res.on('data', (d) => { console.log(cls.getStore()) });
    })
    req.end()
  })
})

In this simple client-server program, the server is sending two chunks of data, forcing the ondata handler to be invoked twice.

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

every time

What is the expected behavior?

I get an empty Map every time in the ondata callback

What do you see instead?

Unfortunately, the store is undefined after the first invocation:

$ node foo.js
Map(1) { 'foo' => '' }
undefined
^C
$

Additional information

If I replace this with a simple timer code, this logic works fine:

const { AsyncLocalStorage } = require('async_hooks');
const cls = new AsyncLocalStorage();

cls.run(() => {
  const store = cls.getStore()
  store.set('foo', 'bar')
  setInterval(() => {
    console.log(cls.getStore().get('foo'))
  }, 1000)
})

$ node timer.js

bar
bar
bar
bar
^C

Am I missing something?

Ping @vdeturckheim

async_hooks confirmed-bug

Source

HarshithaKP

All 7 comments

Thanks @HarshithaKP , it's weird. I'll take a look. But It seems you are using an older version of the API. Did you compile Node.js from sources or did you use the userland module I created to test the API?

vdeturckheim on 3 Mar 2020

@vdeturckheim, thanks for the quick response. I am on Node.js master built from source. My HEAD is at d4e4480093319f6d8f3a26be6aad8c02eb7d589a, were there recent changes went it ?

HarshithaKP on 3 Mar 2020

@HarshithaKP I managed to isolate the bug in executionAsyncResource() (which is the underlying API used by AsyncLocalStorage:

I updated the test test/async-hooks/test-async-exec-resource-http.js:

'use strict';

require('../common');
const assert = require('assert');
const {
  executionAsyncResource,
  executionAsyncId,
  createHook,
} = require('async_hooks');
const http = require('http');

const hooked = {};
createHook({
  init(asyncId, type, triggerAsyncId, resource) {
    hooked[asyncId] = resource;
  }
}).enable();

const server = http.createServer((req, res) => {
  res.write('hello');
  setTimeout(() => {
    res.end(' world!');
  }, 1000);
});

server.listen(0, () => {
  assert.strictEqual(executionAsyncResource(), hooked[executionAsyncId()]);
  http.get({ port: server.address().port }, (res) => {
    assert.strictEqual(executionAsyncResource(), hooked[executionAsyncId()]);
    res.on('data', () => {
      assert.strictEqual(executionAsyncResource(), hooked[executionAsyncId()]);
    });
    res.on('end', () => {
      assert.strictEqual(executionAsyncResource(), hooked[executionAsyncId()]);
      server.close();
    });
  });
});

and now it fails.
CC @mcollina @Qard and @Flarna who understand this mechanism better than me:
basically the resource in the second call to res.on('data', () => { does not seem to be gne through the hook even if it has the same id as the resource on the line before.

vdeturckheim on 3 Mar 2020

❤1

I did a fast look and it seems there is still an issue related to reuse of HTTPParser. On my local machine above test fails on second data event because executionAsyncResource() returns an HTTPParser but hooked[executionAsyncId()] returns an instance of HTTPClientAsyncResource.