pino icon indicating copy to clipboard operation
pino copied to clipboard

Adding requestId prefix to lamda logs ahead of json

Open tonyxiao opened this issue 6 years ago • 13 comments

In lambda, when using console log aws automatically prepends the line with timestamp and request Id. However when using Pino this behavior is lost which makes it harder to find logs by aws @requestId in cloudwatch log insights. In fact in serverless / lambda console, pino logs for a given invocation do not even show up because they are missing this prefix.

image

See example above. Question is - how to replicate lambda's behavior with pino logs?

tonyxiao avatar May 02 '19 21:05 tonyxiao

https://github.com/pinojs/pino/blob/248be4eaf990cec1f06b648df1d3f41f2e503329/pino.js#L122

Pino is writing directly to the stdout file descriptor in its default configuration. I suppose AWS Lambda doesn't trap these writes like it does for console.log writes. You could try specifying your own stream for Pino that writes to console.log.

jsumners avatar May 05 '19 14:05 jsumners

I think you could do something like:

const pino = require('pino')()
exports.handler = function(event, context, callback) {

    console.log('remaining time =', context.getRemainingTimeInMillis());
    console.log('functionName =', context.functionName);
    console.log('AWSrequestID =', context.awsRequestId);
    const logger = pino.child({
      awsRequestId: context.awsRequestId,
    })
    logger.info('hello world');
    callback(null, context.functionName);
};

mcollina avatar May 05 '19 15:05 mcollina

I think you could do something like:

const pino = require('pino')()
exports.handler = function(event, context, callback) {

    console.log('remaining time =', context.getRemainingTimeInMillis());
    console.log('functionName =', context.functionName);
    console.log('AWSrequestID =', context.awsRequestId);
    const logger = pino.child({
      awsRequestId: context.awsRequestId,
    })
    logger.info('hello world');
    callback(null, context.functionName);
};

@mcollina Can you explain why the snippet would work? It's not super obvious to me.

@jsumners Custom stream sounds like a good approach. I assume if we were to write directly console.log then sonic stream is not needed at all right?

tonyxiao avatar May 12 '19 15:05 tonyxiao

@mcollina Can you explain why the snippet would work? It's not super obvious to me.

pino.child() is going to add a property awsRequestId to your newline delimited JSON lines. When/if you load those lines into a capable storage system, then you can query for those id there.

mcollina avatar May 13 '19 16:05 mcollina

@tonyxiao that's entirely up to you. I'm not suggesting implementation details. I'm merely providing an idea.

jsumners avatar May 13 '19 17:05 jsumners

@tonyxiao, did you settle on a solution?

bfelbo avatar Jun 27 '19 23:06 bfelbo

@bfelbo yea I ended up doing console.log. Works well

pino(
      {
        useLevelLabels: true, // TODO: Figure out if this is actually a bad idea
        prettyPrint: config.env.PRETTY_LOGS
          ? { translateTime: true }
          : undefined,
        base: {},
        level: config.env.LOG_EVEL,
      },
      ({
        // Use console.log to write to work w/ lambda
        // @see https://github.com/pinojs/pino/issues/648#issuecomment-489432993
        // https://github.com/pinojs/pino/blob/master/docs/api.md#destination-sonicboom--writablestream--string
        write(buffer: any, cb?: (err?: Error | null) => void) {
          // tslint:disable-next-line:no-console
          console.log(buffer)
          if (cb) {
            cb(null)
          }
          return true
        },
      } as any) as NodeJS.WritableStream,
    )

tonyxiao avatar Jun 28 '19 15:06 tonyxiao

I think we should have a serverless option for pino, pino({serverless: true}) or maybe even require('pino/serverless').

Tbh, I think pino/browser could double up as pino/serverless - the smaller payload/faster init and logging to console are all more suited to serverless.

It would mean losing some features - for instance you wouldn't be able to pretty print. But honestly that is a bad idea on serverless (or server) anyway.. so...

@mcollina @jsumners wdyt?

davidmarkclements avatar Sep 14 '19 17:09 davidmarkclements

I'm not opposed.

jsumners avatar Sep 14 '19 19:09 jsumners

I’m +1. However we need a bit more API parity between the two.

Il giorno sab 14 set 2019 alle 21:02 James Sumners [email protected] ha scritto:

I'm not opposed.

— You are receiving this because you were mentioned.

Reply to this email directly, view it on GitHub https://github.com/pinojs/pino/issues/648?email_source=notifications&email_token=AAAMXY55RQY5JYLK2CJZMBDQJUYLPA5CNFSM4HKIKTWKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD6XCBYY#issuecomment-531505379, or mute the thread https://github.com/notifications/unsubscribe-auth/AAAMXY547SZNLVIR3OAY6IDQJUYLPANCNFSM4HKIKTWA .

mcollina avatar Sep 14 '19 19:09 mcollina

yeah.. also there's things in browser that don't apply to serverless, e.g. transmit option

I think we could extract most of browser.js into something like a nano.js file, and then consume it from pino/serverless and pino/browser.

Then optionally pino/nano can be for browser/serverless/IoT when minimum optionality for smallest possible payload makes sense

davidmarkclements avatar Sep 14 '19 20:09 davidmarkclements

For what it's worth, we have a library built on top of Pino that we use for logging in a lambda context at Cazoo: https://www.npmjs.com/package/cazoo-logger

bobthemighty avatar Nov 12 '19 09:11 bobthemighty

The above solutions didn't quite fit the native Cloudwatch format, so I created a drop in wrapper that preserves the native cloudwatch format.

https://www.npmjs.com/package/pino-lambda

carbonrobot avatar Jan 04 '21 15:01 carbonrobot

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

github-actions[bot] avatar Mar 20 '23 00:03 github-actions[bot]