AsyncLocalStorage instance shared between several http requests

[dolphin278]

Version

v17.5.0

Platform

Linux DESKTOP 5.10.60.1-microsoft-standard-WSL2 #1 SMP Wed Aug 25 23:20:18 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Subsystem

async_hooks

What steps will reproduce the bug?

Opening localhost:3000/ in Chrome (keep-alive) shows that we have access to the same instance of AsyncLocalStorage when we serve both / and /favicon.ico. I would understand if both of them were coming from the same async resource representing connection and there was no distinction, but log (see below) produced by async hooks shows that there was two separate HTTPINCOMINGMESSAGE but when it comes to request listener suddenly we have same asyncId.

May be it is not a bug, but observed behavior is very confusing. I've read that

import * as http from "node:http";
import * as events from "node:events";
import * as async_hooks from "node:async_hooks";

await events.once(http.createServer(httpHandler).listen(3000), "listening");
console.log("server started");
const currentRequest = new async_hooks.AsyncLocalStorage();

// Create hook to ensure t
async_hooks
  .createHook({
    init(asyncId, type) {
      if (type === "TickObject" || type === "TickTimeout") return;
      console.log(asyncId, type);
    },
  })
  .enable();

function getCurrentRequestExn() {
  const current = currentRequest.getStore();
  if (!current) throw new Error("no current request");
  return current;
}

function setCurrentRequest(req) {
  console.log(
    "setCurrentRequest %s %d",
    req.url,
    async_hooks.executionAsyncId()
  );
  const existing = currentRequest.getStore();
  if (existing !== void 0) throw new Error("current request already set");
  currentRequest.enterWith(req);
}

function httpHandler(req, res) {
  setCurrentRequest(req);
  if (req.url === "/") res.end(route1());
  else if (req.url === "/favicon.ico") res.end(route2());
}

function route1() {
  const req = getCurrentRequestExn();
  return "route1 " + req.url;
}

function route2() {
  const req = getCurrentRequestExn();
  return "route2" + req.url;
}

Log produced:

server started
20 TCPWRAP
22 HTTPINCOMINGMESSAGE
24 TCPWRAP
26 HTTPINCOMINGMESSAGE
setCurrentRequest / 22
29 Timeout
34 Timeout
setCurrentRequest /favicon.ico 22

And, since we accessing same instance of the async local storage - then there is an exception:

file:///home/dolphin/projects/komsomol/server.js:33
  if (existing !== void 0) throw new Error("current request already set");
                           ^

Error: current request already set
    at setCurrentRequest (file:///home/dolphin/projects/komsomol/server.js:33:34)
    at Server.httpHandler (file:///home/dolphin/projects/komsomol/server.js:38:3)
    at Server.emit (node:events:526:28)
    at parserOnIncoming (node:_http_server:951:12)
    at HTTPParser.parserOnHeadersComplete (node:_http_common:128:17)

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

All the time.

What is the expected behavior?

Separate instances of AsyncLocalStorage for each request, or some explanation in documentation on how to achieve it.

What do you see instead?

Same instances of AsyncLocalStorage shared between http requests contexts when requests made using keep-alive connection.

Additional information

No response

[Flarna]

@nodejs/async_hooks

[Flarna]

I'm not able to reproduce the exact problem you reported. In my case the same HTTPINCOMINGMESSAGE is reused for a keep alive connection. Result is more or less the same.

One note: you use the unbound als.enterWith(store) which sets the store on the current resource forever. If you would use als.run(store, cb) instead it would be only for the given cb. As a result your second request would not see the store of the first.

[dolphin278]

@Flarna Thank you for your answer. What OS you using?

I've tried using .run() and now we have clean environment in each request (no exception was triggered, see the source code below) which is great. Still, according to log file we still have same async id during two httpHandler invocations (see 'Log file' below), may be I miss something (not really a problem but looks strange).

I tried using .run() before, but it did not worked for me, could be because I had more complicated setup with async functions and promises).

Source code

import * as http from "node:http";
import * as events from "node:events";
import * as async_hooks from "node:async_hooks";
import * as fs from "node:fs";

await events.once(http.createServer(httpHandler).listen(3000), "listening");
fs.appendFileSync("./log2.txt", "server started\n");
const currentRequest = new async_hooks.AsyncLocalStorage();

// Create hook to ensure t
async_hooks
  .createHook({
    init(asyncId, type) {
      if (type === "TickObject" || type === "TickTimeout") return;
      fs.appendFileSync("./log2.txt", "init " + asyncId + " " + type + "\n");
      // console.log(asyncId, type);
    },
  })
  .enable();

function getCurrentRequestExn() {
  const current = currentRequest.getStore();
  if (!current) throw new Error("no current request");
  return current;
}

function httpHandler(req, res) {
  const curReq = currentRequest.getStore();
  if (curReq !== void 0) {
    // This exception is not thrown so environment is clean
    throw new Error("current request already set");
  }
  currentRequest.run(req, () => {
    fs.appendFileSync(
      "./log2.txt",
      "http handler " + async_hooks.executionAsyncId() + "\n"
    );
    // console.log("http handler", async_hooks.executionAsyncId());
    if (req.url === "/") res.end(route1());
    else if (req.url === "/favicon.ico") res.end(route2());
  });
}

function route1() {
  const req = getCurrentRequestExn();
  return "route1 " + req.url;
}

function route2() {
  const req = getCurrentRequestExn();
  return "route2" + req.url;
}

Log file

server started
init 12 TCPWRAP
init 13 HTTPINCOMINGMESSAGE
init 15 TCPWRAP
init 16 HTTPINCOMINGMESSAGE
http handler 13
init 18 Timeout
init 23 Timeout
http handler 13
init 34 Timeout
init 41 TTYWRAP
init 42 SIGNALWRAP

[benjamingr]

Looks like this is by-design and the correct thing was to use run.

@dolphin278 would you be interested in making a docs PR to the ALS docs to see if this is something that can/should be explained better?

[Flarna]

@benjamingr I'm not sure here. Reusing the same Resource for several requests seems not correct to me. Usually AsyncResource or similar should be used to avoid something like this. We fixed similar issues in the past for outgoing HTTP where sockets were reused by an keep alive agent.

I will take a closer look what happens in detail here once I find some more time.

[dolphin278]

@benjamingr I've read through the docs again and now I don't understand how could I miss that .enterWith() sets store in a way that persists value across async contexts :-(

I don't think anything needs to be done with docs atm.

From my side this issue is resolved, if anything else will come up I'll open another one.

[Flarna]

Regarding reuse of resource/id I found the relevant ToDo in code.

The HTTP parser is reused on a HTTP server socket therefore all requests on the same socket get the same asyncId.

[dorshay6]

Hi any update in here?

[Flarna]

I did a look into this a while ago but found no fast solution. Moved to other topics then and never found time to came back to this.

[crysislinux]

I feel like I have a similar issue. We have two requests that happen to be fired within a very short time (almost the same time) from the browser. Then we can see the two requests read the same store. But it does not always happen, sometimes they read different stores. Adding a random delay between the requests (on the client side) makes the issue disappear. This makes me feel really unsafe when using it.

[lroal]

Any news on this ?
I am still using the deprecated Domain because I don't trust AsyncLocalStorage / async_hooks. I have had the same experience with two requests getting the same asyncId when fired almost at the same time.

[benjamingr]

@nodejs/async_hooks