Adding requestId prefix to lamda logs ahead of json

[tonyxiao]

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.

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

[jsumners]

pino/pino.js

Line 122 in 248be4e

pino.destination = (dest = process.stdout.fd) => buildSafeSonicBoom(dest, 0, true)

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.

[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);
};

[tonyxiao]

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?

[mcollina]

@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.

[jsumners]

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

[bfelbo]

@tonyxiao, did you settle on a solution?

[tonyxiao]

@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,
    )

[davidmarkclements]

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?

[jsumners]

I'm not opposed.

[mcollina]

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 <notifications@github.com> ha scritto:

…

I'm not opposed. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#648?email_source=notifications&email_token=AAAMXY55RQY5JYLK2CJZMBDQJUYLPA5CNFSM4HKIKTWKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD6XCBYY#issuecomment-531505379>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAMXY547SZNLVIR3OAY6IDQJUYLPANCNFSM4HKIKTWA> .

[davidmarkclements]

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

[bobthemighty]

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

[carbonrobot]

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