AsyncLocalStorage not working on Nodejs 13.11.0

[averri]

• Version: v13.11.0
• Platform: Linux alex-ubuntu 4.15.0-88-generic Proposal: return Promises as well as taking callbacks. #88-Ubuntu SMP Tue Feb 11 20:11:34 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem:

What steps will reproduce the bug?

Please refer the following code to reproduce the issue.

package.json:

{
  "name": "async-local-storage-demo",
  "version": "1.0.0",
  "dependencies": {
    "@feathersjs/express": "^4.5.2",
    "@feathersjs/feathers": "^4.5.2",
    "@feathersjs/socketio": "^4.5.2",
    "@feathersjs/socketio-client": "^4.5.2",
    "socket.io-client": "^2.3.0"
  }
}

server.js:

const feathers = require('@feathersjs/feathers')
const express = require('@feathersjs/express')
const socketio = require('@feathersjs/socketio')
const {AsyncLocalStorage} = require('async_hooks')

const storageKey = '_logData'
const storage = new AsyncLocalStorage()

// Logs to console, adding extra information from async local storage.
const info = (...args) => {
  const store = storage.getStore()
  const context = store ? store.get(storageKey) : {status: '<undefined store>'}
  console.info(`${new Date().toISOString()}`, {...context}, ...args)
}


class MessageService {
  async find() {
    info('Invoking find') // This should log additional data from the client.
    return 'Hello from the server'
  }
}

// Creates an ExpressJS compatible Feathers application
const server = express(feathers())

// Parse HTTP JSON bodies
server.use(express.json())
// Parse URL-encoded params
server.use(express.urlencoded({extended: true}))
// Host static files from the current folder
server.use(express.static(__dirname))
// Add REST API support
server.configure(express.rest())

// Configure Socket.io real-time APIs
server.configure(socketio(io => {
  // https://docs.feathersjs.com/api/socketio.html#params
  io.use((socket, next) => {
    // Get the user agent from the request.
    const userAgent = socket.conn.request.headers['user-agent']
    // Make information available to async local storage (for logging).
    storage.run(new Map(), () => {
      storage.getStore().set(storageKey, {userAgent})
      next()
    })
  })
}))


// Register a messages service
server.use('/messages', new MessageService())
// Register a nicer error handler than the default Express one
server.use(express.errorHandler())


// Start the server
server.listen(3030).on('listening', () =>
  console.log('Feathers server listening on localhost:3030')
)

client.js:

const feathers = require('@feathersjs/feathers')
const socketio = require('@feathersjs/socketio-client')
const io = require('socket.io-client')

const debug = text => console.debug(`${new Date().toISOString()}: ${text}`)

// https://socket.io/docs/client-api/
function getAPI(url) {

  const api = feathers()

  const socket = io(url, {
    transports: ['websocket'], // Connect using websocket only.
    path: '/socket.io',
    extraHeaders: {
      'user-agent': 'Feathersjs client'
    }
  })

  api.configure(socketio(socket))

  socket.on('disconnect', () => {
    debug('Disconnected')
  })

  socket.on('reconnecting', n => {
    debug(`Reconnecting (${n})...`)
  })

  socket.on('reconnect', n =>  {
    debug(`Reconnected after ${n} tries`)
  })

  socket.on('connect', () => {
    debug('Connected')
  })

  return api
}

const api = getAPI('http://localhost:3030')

// Invoke the service 'messages' and print the response.
// This will trigger the scenario showing the issue with AsyncLocalStorage.
api.service('messages').find({}).then(console.info)

Run the server:

node server.js

Run the client:

node client.js

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

Always.

What is the expected behavior?

When the client.js starts the server.js log should print the information retrieved from AsyncLocalStorage API:

2020-03-17T18:25:13.367Z {userAgent: 'Feathersjs client' } Invoking find

What do you see instead?

The AsyncLocalStorage API return an undefined store:

2020-03-17T18:25:13.367Z { status: '<undefined store>' } Invoking find

[gireeshpunathil]

@averri - I did not run the test so not making any inferences, but:

io.use((socket, next) => {
    // Get the user agent from the request.
    const userAgent = socket.conn.request.headers['user-agent']
    // Make information available to async local storage (for logging).
    storage.run(new Map(), () => {
      storage.getStore().set(storageKey, {userAgent})
      next()
    })
  })

As per the spec, in my understanding, storage.run should encompass the call to the function that is asynchronous, and the store, if populated, will be made available to all the calls emanating from the said function.

In this case I don't see that top level asynchronous function. Probably you may want to elevate the storage.run to the outer call (io.use)? this is just a speculation, I don't know enough about this module to say which is the overarching async call and which are the callbacks coming out of it.

/cc @vdeturckheim

[vdeturckheim]

@averri I am not clear about the sequence of calls in your example (mostly because I am unfamiliar with the Feather framework).
I can't really get a tacktrace of the call to MessageService.prototype.find. Can you clarify what calls it?

Also cc-ing @puzpuzpuz, @Qard and @Flarna :)

[Qard]

Probably something in feathers is doing something indirectly async, similar to connection pooling, and not using an AsyncResource to keep track of the context. 🤔

[Flarna]

I would also assume that this is caused by some connection pooling or similar within feathers or some module used by it (e.g. for websockets) as mentioned by @Qard
AsyncLocalStorage relies on async_hooks which in turn rely on user space modules using AsyncResource to model their operations in case they use connection pooling or some native addon.

[averri]

Thanks to all folks who answered here. I initially thought it could be related to Nodejs, but I agree with all the comments here. I have requested help in the Feathersjs repository.

[averri]

Hi @vdeturckheim, thanks for your comment. I do not know the internals of the SocketIO middleware and how it calls the framework service methods. But I do know how to extend the functionality of the service methods by using mixins. I was able to get it working for service methods, but the store context is lost when the service method throws an exception.

Changing the server.js to add support for the AsyncLocalStorage (partially working):

const feathers = require('@feathersjs/feathers')
const express = require('@feathersjs/express')
const socketio = require('@feathersjs/socketio')
const {AsyncLocalStorage} = require('async_hooks')

const storage = new AsyncLocalStorage()

// Logs to console, adding extra information from async local storage.
const info = (...args) => {
  const store = storage.getStore() || {status: '<undefined store>'}
  console.info(`${new Date().toISOString()}`, {...store}, ...args)
}


class MessageService {
  async find() {
    info('Invoking find') // This should log additional data from the client.
    return 'Hello from the server'
  }
}

// Creates an ExpressJS compatible Feathers application
const app = express(feathers())

// Parse HTTP JSON bodies
app.use(express.json())
// Parse URL-encoded params
app.use(express.urlencoded({extended: true}))
// Host static files from the current folder
app.use(express.static(__dirname))
// Add REST API support
app.configure(express.rest())

// Configure Socket.io real-time APIs
app.configure(socketio(io => {
  io.use((socket, next) => {
    const userAgent = socket.conn.request.headers['user-agent']
    socket.feathers.store = { userAgent }
    next()
  })
}))

// The new mixin to create the async local storage.
app.mixins.push((service, path) => {
  Object.entries(service.methods).forEach(([method, params]) => {
    const paramsIdx = params.indexOf('params')
    const serviceMethod = service[method]
    service[method] = (...args) => {
      const params = args[paramsIdx]
      storage.enterWith(params.store)
      return serviceMethod.apply(service, args) // The store will be available to the service method, but the context will get lost if any exception is thrown.
    }
  })
})

// Register a messages service
app.use('/messages', new MessageService())

// Register a nicer error handler than the default Express one
app.use(express.errorHandler())

// Start the server
app.listen(3030).on('listening', () =>
  console.log('Feathers server listening on localhost:3030')
)

I have seen the AsyncLocalStorage working as specified, so I'm closing this issue now.