Request ID logging

[mnapoli]

Here are some notes about logging with the AWS request ID.

The goal

Be able to see all logs of a single invocation.

How? By filtering using the "request ID".

How? By storing that request ID in each log record.

Is it not there already? It's there when logging from a JS lambda for example.

When logging from PHP (by writing to stdout/stderr), only the START, END and REPORT log lines contain it (the lines written by Lambda itself).

NodeJS runtime

exports.handler = async () => {
    console.log('Hello from Lambda!');
};

This is what we see in CloudWatch:

This is the same thing in Insights:

Analysis: the request ID is added in a non-structured text line. Values are separated by tabs (\t). For example:

2020-03-13T21:21:56.341Z 0879de55-0817-4d5c-9f37-7ed2755a72e1 INFO Hello from Lambda! 

Current Bref PHP runtime

echo 'Hello world';

In CloudWatch:

In Insights:

Analysis: the @requestId field (or the request ID value itself) does not appear in that record.

Experiment 1

echo json_encode([
        'message' => 'Hello world!',
        'requestId' => $context->getAwsRequestId(),
        '@requestId' => $context->getAwsRequestId(),
]) . PHP_EOL;

In CloudWatch:

In Insights:

Analysis: it looked promising at first, but it turns out the @requestId field is escaped to @@requestId by CloudWatch (or Lambda?).

That means that we still have no @requestId field. For example, this query does not return the lines we logged in PHP:

fields @message
| filter @requestId = '6dc9b447-3898-4793-83cf-60730058c833'

Experiment 2

Based on the tabulated format from the JS runtime, could it be that CloudWatch interprets data that way?

echo "2020-03-13T21:21:56.341Z\t{$context->getAwsRequestId()}\tINFO\tHello world" . PHP_EOL;

CloudWatch:

Insights:

Analysis: OMG it works!!!

The field is correctly recognized now:

Even serverless logs parsed the fields:

[mnapoli]

Experiment 3

echo $context->getAwsRequestId() . "\tHello world\n";

CloudWatch:

Insights:

Analysis: worked too! The log message is simpler, easier to read as well. However it's not colored in the terminal by serverless logs:

The serverless logs color come from here: https://github.com/serverless/serverless/blob/f822ae7e4c4062178b9f6843104fb33f0a586ef5/lib/plugins/aws/utils/formatLambdaLogEvent.js#L21-L43

[mnapoli]

Experiment 4

Same as experiment 3, but in the case where we want to log structured data with JSON:

echo "{$context->getAwsRequestId()}\t" . json_encode([
    'message' => 'This is a message',
]) . PHP_EOL;

(yes we mix string and JSON content, CloudWatch supports it on purpose)

Seems to work perfectly as well!

Just tested on NodeJS as well to confirm, they do the same thing:

2020-03-13T22:12:01.928Z	206e2f13-4cc3-415b-8ed2-a5b108111680	INFO	{ message: 'Hello from Lambda!' }

[mnapoli]

OK now the difficulty is: the request ID is scoped at the invocation level.

The logger is scope at the application level.

How do we combine this properly 🤔

[mnapoli]

For reference, here is JS code that is responsible for formatting console.log() in the NodeJS runtime:

function patchLogging(invokeId) {
    console.log = console.error = console.warn = console.info = function prettyConsoleLog() {
        var dateString = new Date().toISOString();
        var message = `${dateString}\t${invokeId}\t${util.format.apply(this, arguments)}\n`;
        awslambda.sendConsoleLogs(message, Buffer.byteLength(message));
    };
};

Digging further:

sendConsoleLogs: consoleLog,

function formatConsole(str) {
  return str.replace(/^[0-9TZ:.-]+\t[0-9a-f-]+\t/, '\u001b[34m$&\u001b[0m')
}

function consoleLog(str) {
  process.stderr.write(formatConsole(str))
}

function systemLog(str) {
  process.stderr.write(formatSystem(str) + '\n')
}

function systemErr(str) {
  process.stderr.write(formatErr(str) + '\n')
}

function handleResult(resultStr, cb) {
  if (!process.stdout.write('\n' + resultStr + '\n')) {
    process.stdout.once('drain', cb)
  } else {
    process.nextTick(cb)
  }
}

So it is reassuring: the NodeJS runtime indeed logs via stderr, just like we do in PHP.

For a long time I thought they used a secret technique for logging with the @requestId variable, but it seems to be AWS CloudWatch that has a secret behavior of parsing the \t separated values. Hooray 🎉

[mnapoli]

Before dealing with all the log lines, we can start applying all that to exceptions/errors: see brefphp/bref#590

[ctessmer]

@mnapoli I love how thorough you are in your notes! And that you make them public.

I just started using Github as a place to document my personal journey through issues in my private repos (as you know). At first I thought, "Oh man Christian, this is too much. You're wasting time."

But I know the the future me will really love this when I inevitably forget how to configure a serverless setting 2+ years from now.

I guess what I'm saying is thank you for:

1. Affirming, indirectly, that I'm not crazy for doing the same and
2. For writing this up.

Watching someone else solve problems in "real time" helps me learn to be a better problem solver.

Excellent work as always man! 💯