Integrating Feathersjs with AsyncLocalStorage

[averri]

The new AsyncLocalStorage API, introduced with Nodejs 13.10.0, is a great tool for improving logging, security and other aspects of the framework. It can be used, for example, to store request data like userId, userAgent, IP, etc, and make this information available to the logging API without having to pass these data via function calls.

My first tentative of integrating the AsyncLocalStorage with the REST middleware worked well, but the same is not working for the SocketIO middleware, I thought it could be related to a bug in the Nodejs implementation, but it seems that the AsyncLocalStorage is not being used correctly with SocketIO middleware.

In order to make it to work, it needs to identify what is the parent function call on Feathersjs SocketIO middleware that remains active in the stack during the handling of a client message.

Question: what is the best place to put the call to storage.run function in the SocketIO middleware? The best place should be around any client request, like:

<request from client/>
// Store data into AsyncLocalStorage at this point
<start of service call 1>  // Data is available to all service calls descending from here
     <start of service call 2>
          <start of service call 3>
          <response of service call 3>
     <response of service call 2>
<response of service call 1>
<response to client/>

Please vide https://github.com/nodejs/node/issues/32330 for more information.

[daffl]

The problem is that Socket IO middleware only runs once when the connection is established, not for every request. Probably related to https://github.com/feathersjs/feathers/issues/1854 to allow tie into the transport method runner (https://github.com/feathersjs/feathers/blob/master/packages/transport-commons/src/socket/utils.ts#L65)

[averri]

Hi @daffl, I think you have forgotten about this construction:

  app.configure(socketio(io => {
    // https://docs.feathersjs.com/api/socketio.html
    io.use((socket, next) => {
      // At this point we have one context per client request.
      socket.feathers.store = {
        clientIP: socket.conn.remoteAddress, 
      }
      next()
    })
  }))

... which gives access to every client request using SocketIO.

[daffl]

It does but you'd have to pass those params along to every other internal call (which is the currently recommended way).

What AsyncLocalStorage allows is to get access to things set in its context in nested calls even if you don't pass it along.

[averri]

This is what I tried without success:

const {AsyncLocalStorage} = require('async_hooks')
// other code...
const storage = new AsyncLocalStorage()

app.configure(socketio(io => {
  io.use((socket, next) => {
    const userAgent = socket.conn.request.headers['user-agent']
    // Make information available to async local storage (for logging).
    storage.run(new Map(), () => {     // As specified by AsyncLocalStorage API
      storage.getStore().set(storageKey, {userAgent})
      next() // Call the next middleware. The async context gets lost here.
    })
  })
})

[daffl]

See my first comment https://github.com/feathersjs/feathers/issues/1881#issuecomment-600807093 - it might be possible with an app service mixin

[averri]

Yeah, I created a service mixin and it does work partially. The context gets lost when there is an exception in the hooks or service methods:

The complete server.js code:

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')
)

[daffl]

Do you have a non-Feathers example of AsyncLocalStorage handling exceptions?

[averri]

Hi David, please see this example. It's a modification of the original Nodejs documentation at https://nodejs.org/api/all.html#async_hooks_class_asynclocalstorage.

const {AsyncLocalStorage} = require('async_hooks')

const kReq = 'CURRENT_REQUEST'
const asyncLocalStorage = new AsyncLocalStorage()

function log(...args) {
  const store = asyncLocalStorage.getStore()
  if (store && store.has(kReq)) {
    const req = store.get(kReq)
    console.log(req.method, req.path, ...args)
  } else {
    console.log('<undefined async local storage>', ...args)
  }
}

async function invokeService(path) {
  return new Promise(async (resolve, reject) => {
    log('INFO', 'service') // Data from the AsyncLocalStorage.
    if (path === '/resolve') {
      const result = await invokeAnotherService()
      resolve(result)

    } else if (path === '/reject') {
      reject({status: 'error'})

    } else {
      throw new Error('Unexpected error')
    }
  })
}


async function invokeAnotherService() {
  log('INFO', 'anotherService')
  return {status: 'ok'}
}


function handleRequest(request) {
  asyncLocalStorage.run(new Map(), () => {
    const store = asyncLocalStorage.getStore()
    store.set(kReq, request)
    const {path} = request
    invokeService(path)
      .then(result => {
        log('INFO', 'response', result)  // Data from the AsyncLocalStorage.
      })
      .catch(error => {
        log('ERROR', 'response', error) // Data from the AsyncLocalStorage.
      })
  })
}

process.on('unhandledRejection', error => {
  log('unhandledRejection', error.message) // Here the AsyncLocalStorage has no context.
})


handleRequest({method: 'GET', path: '/resolve'})
handleRequest({method: 'GET', path: '/reject'})
handleRequest({method: 'GET', path: '/throw'})

This should print:

GET /resolve INFO service
GET /resolve INFO anotherService
GET /reject INFO service
GET /throw INFO service
GET /resolve INFO response { status: 'ok' }
GET /reject ERROR response { status: 'error' }
<undefined async local storage> unhandledRejection Unexpected error

In summary, if the exception is thrown and captured inside the scope of the function run, it will have access to the AsyncLocalStorage scope. In the case of the unhandledRejection, it does not have access to the scope anymore.

[averri]

This also work:

function handleRequest(request) {
  const store = new Map()
  store.set(kReq, request)
  asyncLocalStorage.enterWith(store)
  const {path} = request
  invokeService(path)
    .then(result => {
      log('INFO', 'response', result)
    })
    .catch(error => {
      log('ERROR', 'response', error)
    })
}