Equipping plugins or functions with reqId

[rhettjay]

Has anyone attempted to equip functions in a plugin with the request id?
For example:
If I were to have a plugin that registers a route which contains a call to a database and I want to know the duration of database calls, I might presently pass in the reqId as a parameter to my db wrapper and log that directly after the database response is returned.

// index.js
...

import { db } from './plugins/db'
let fastify = Fastify()

fastify.register(db, {dbOptions}
...

// plugins/db.js
import { routeQuery } from './routes/query.js'
...

export const db async (fastify, options) {
  const { db } = options

  function dbDecorator (request, reply, done) {
	request.db = db
	done()
  }

  fastify.addHook('onRoute', (route) => { route.onRequest = [dbDecorator] })

  await fastify.register(routeQuery, routeOpts)
}

// routes/query.js

const route FastifyPluginAsync = async function (fastify, opts) {
  fastify.get('/', { schema: { querystring, response }, async (request, reply) => {
	
  //blah blah blah... prep query string for query

  await request.db.query(blah blah)
	
  return data
  })
}

export default route

For example, in the above code base I would potentially pass in the requestId to the query function if I'm using a wrapper that I can manipulate. Then I can add log statements around the actual query.

// routes/query.js
...
await request.db.query(request.id, blah blah)

// db/query.js
...
	
  async query (reqId, blah blah) {
	const queryStart = process.hrtime()

	let data = await client.query(sql`blah blah`)

	const queryEnd = process.hrtime(queryStart)
	logger.info({ time_in_query: queryEnd blah blah, reqId })

	return data
  }

This feels like the wrong way to do it, because I'm logging several more lines. If I'm using a package like atdatabases it gets even more excessive if I need to add things like onQueryStart, onQueryError, onConnection, etc. At this point I'd be getting 4-5 logs per request. Perhaps overwhelming downstream consumers (either from an ingestion or just from a data overload standpoints)

Instead I'd like to be able to add this information to the default configuration s.t. other performance metrics can be added as they are collected. This way I'm reducing the overall footprint of the logs by adding one or two lines to one log.

//Request
{
  "level":"info",
  "time":1697642485460,
  "reqId":"req-1",
  "req":{ 
    "method":"GET",
	"url":"/health",
	"hostname":"localhost:8080",
	"remoteAddress":"127.0.0.1",
	"remotePort":52395
  },
  "message":"incoming request"
}
//Response
{
  "level":"info",
  "time":1697642485464,
  "reqId":"req-1",
  "res":{
    "statusCode":200
  },
  "responseTimes":
  {
    "totalTime": 4.014708995819092
    "timeInQuery":foo,
    "timeInFooApi":bar,
	...
},
  "message":"request completed"
}

I'm thinking a hook might be the way to go, but I keep getting stuck on the implementation there and thought I would poll the community. Has anyone tried this approach before? What implementation method did you use?

[Eomm]

You can do it already with open telemetry:

• https://github.com/PacktPublishing/Accelerating-Server-Side-Development-with-Fastify/tree/main/Chapter%2013
• https://www.npmjs.com/package/@opentelemetry/instrumentation-fastify

[rhettjay]

Grazie @Eomm! What are the performance implications when implementing open telemetry?

I would imagine it's not insignificant to have distributed node-traces running in the background. Certainly the tradeoff is worth it at times to understand the perf of the code. That being said, I can also imagine a scenario where I'm logging or tracing so much that I'm actually causing my own through trying to diagnose it, no? Your thoughts?

[Uzlopak]

When using opentelemetry, you are imho sending the info per UDP to the telemetry server. So basically it is fire and forget. Obviously there is a small overhead, but it should be negligible.

[metcoder95]

Usually, the biggest shot at performance comes with the usage of the async_hooks as OTEL uses it often to create the context for the spans made out of traces. There are efforts at node's core t move away from them but it will take time until the work is wrapped, as later on adopted by the OTEL tooling

[rhettjay]

Noted, thank you both!