How to add co-relationId to pino logger with middy in serverless application using cls-proxify

[s1mrankaur]

Our logger.js that uses pino library looks like this:

  import pino from "pino";
   const logger = pino({ name: 'viewLinc', level: process.env.STAGE == 'prod' ? 'info' : 'debug' });
   export default logger;

When using logger, we simply say

    import logger.js
    logger.info("bla bla bla:)

we are also using middy in the application. Middy generates traces with requestId in traces in the ServiceLens but we do not see our custom logs there. For that matter, we will need to add our requestId/co-relationId to the logger object.

Common-middleware.js in our application looks like this:

    export default handler => middy(handler).use([
    loggerMiddleware({ logger: logger }), 
    //.....other middleware 
    httpErrorHandler(), ]);

How can I centrally add co-relationId in my custom logs using cls-proxify so that they will show up in the traces without having to leave it up to the developers to do it?

[aigoncharov]

I guess it should be something along these lines

import pino from "pino";
import { clsProxify, clsProxifyNamespace } from 'cls-proxify'

const logger = pino({ name: 'viewLinc', level: process.env.STAGE == 'prod' ? 'info' : 'debug' });
// wrap your logge with a proxy to get the request ID from the CLS
const loggerCls = clsProxify('requestId', logger)

export default loggerCls;

export default handler => middy(handler).use([
    () => {
      // Set  `requestId` in CLS to `requestId/co-relationId` so proxified pino picks it up
      setClsProxyValue('requestId', somehowGetValueOfRequestId-co-relationId())
    },
    loggerMiddleware({ logger: logger }), 
    //.....other middleware 
    httpErrorHandler(), ]);

[s1mrankaur]

@aigoncharov 1.

1. It throws " Middleware must be an object" at

 () => {
      // Set  `requestId` in CLS to `requestId/co-relationId` so proxified pino picks it up
      setClsProxyValue('requestId', somehowGetValueOfRequestId-co-relationId())
    },

I also tried

const baseHandler = (event, context) => {
  /* your business logic */
  // Set  `requestId` in CLS to `requestId/co-relationId` so proxified pino picks it up
  setClsProxyValue('requestId', 'testId')
}

// Export anonymous function
export default handler => middy(baseHandler).use([

])

and in this case, it throws :

**No context available. ns.run() or ns.bind() must be called first.**

2. If it was working, wherever I say

  import logger.js
  logger.info("bla bla bla:)

will have the requestId although
setClsProxyValue('requestId', somehowGetValueOfRequestId-co-relationId())

is in the middleware and not where the logger object is created?

[aigoncharov]

@s1mrankaur I suggest you use https://github.com/aigoncharov/cls-proxify#any-other-framework-or-library as an example.
I have never used middy myself, but they seems to have a good section in their docs on writing middleware - https://github.com/middyjs/middy#writing-a-middleware. With that knowledge combined, it should be possible to write a CLS_enabled middleware.
Essential steps:

• Create CLS context to run your request in via clsProxifyNamespace.run
• Assign a request ID to a key in your CLS
• Use that key to wrap your logger with a proxy

[s1mrankaur]

@s1mrankaur I suggest you use https://github.com/aigoncharov/cls-proxify#any-other-framework-or-library as an example.
I have never used middy myself, but they seems to have a good section in their docs on writing middleware - https://github.com/middyjs/middy#writing-a-middleware. With that knowledge combined, it should be possible to write a CLS_enabled middleware.
Essential steps:

• Create CLS context to run your request in via clsProxifyNamespace.run
• Assign a request ID to a key in your CLS
• Use that key to wrap your logger with a proxy

@aigoncharov If it was working, wherever I say

  import logger.js
  logger.info("bla bla bla:)

will have the requestId although
setClsProxyValue('requestId', somehowGetValueOfRequestId-co-relationId())
is in the middleware and not where the logger object is created?

Can you confirm this please?

[aigoncharov]

@s1mrankaur yes, this is correct.

[s1mrankaur]

@aigoncharov Changed the middy handler as follows according to the steps in last message:

export default handler => middy(handler).
  before((async () => {
    const { context } = handler
    clsProxifyNamespace.run(() => {     //STEP 1
      const loggerProxy = {
        debug: (msg) => `${context.awsRequestId}: ${msg}`,
      }
      setClsProxyValue('requestId', loggerProxy);   //STEP 2
    });
   }))
   .use([
    loggerMiddleware({ logger: logger }),
]);

In pino-logger.ts:

import pino from "pino";
import { clsProxify, clsProxifyNamespace } from 'cls-proxify'

const logger = pino({ name: 'viewLinc', level: process.env.STAGE == 'prod' ? 'info' : 'debug' });
// wrap your logge with a proxy to get the request ID from the CLS
const loggerCls = clsProxify('requestId', logger)                           //STEP 3

export default loggerCls;

Added all 3 steps, Still nothing in traces though.

[aigoncharov]

This looks great! You seem to be on the right track.
Notice, how in the example in documentation we call 'next' inside of the 'namesapce.run'. It runs the rest of the request in the CLS context. You need to figure out something like that for middy

[s1mrankaur]

@aigoncharov next() is deprecated in middy and the recommended way to do it is:

middy(handler).before((async () => {})

[s1mrankaur]

Just to post the solution, https://www.npmjs.com/package/pino-lambda worked well for us. Thanks for your support.