Bug: Under load stdout writes are buffered and lost on lambda runtime termination

[slewis77]

Expected Behavior

We log a lot of data to CW that has a field index for searching. These are logged at INFO level using Logger. These arrive in large batches from Firehose

We expect all data to be logged successfully in CW

Current Behavior

Under load we find that the underlying stdout write isn't immediately flushed and is queued in memory by the underlying stream. I think this is internal to the writes made via the Console object.

When this happens, nothing waits for that buffer to be freed up and when the lambda completes and the runtime is terminated, that queue is lost and the data isn't written

Note: This is not the same buffer as you get with DEBUG logs in Logger.

This is the docs from the underlying stream write:

/**
* Sends data on the socket. The second parameter specifies the encoding in the
* case of a string. It defaults to UTF8 encoding.
*
* Returns `true` if the entire data was flushed successfully to the kernel
* buffer. Returns `false` if all or part of the data was queued in user memory.`'drain'` will be emitted when the buffer is again free.
*
* The optional `callback` parameter will be executed when the data is finally
* written out, which may not be immediately.
*/

Code snippet

export const logSomething = async (message: ExampleMessage, logger: Logger) => {
  for (const entry of message.results) {
    logger.info('SOME_VALUE', {
      item1: entry.item1,
      item2: entry.item2,
    });
  }
};

Steps to Reproduce

Create a lambda with a known log message at the start and end
Trigger the lambda with data in the event or hardcoded that has a large array of items (in the region of 10,000 items 200 byte objects) to log individually
Add code to the lambda to iterate over the array logging each item
Check the cloudwatch logs, if reproduced you will see the start log message and many of the logged objects, but likely not the end message as the lambda was terminated before the queued data was written

Possible Solution

Add a promise around the socket's drain callback and resolve when fully complete

Powertools for AWS Lambda (TypeScript) version

latest

AWS Lambda function runtime

22.x

Packaging format used

npm

Execution logs

[boring-cyborg]

Thanks for opening your first issue here! We'll come back to you as soon as we can.
In the meantime, check out the #typescript channel on our Powertools for AWS Lambda Discord: Invite link

[dreamorosi]

Hi @slewis77 thanks for opening this issue.

As you've correctly mentioned, this happens because of an internal implementation detail of the underlying Console module.

Could you please expound on what you mean by this? I understand the concept but I'm not sure how it'd look in practice:

Add a promise around the socket's drain callback and resolve when fully complete

In the meantime, could you try adding these lines and seeing if the logs are drained correctly?

if (process.stdout._handle) process.stdout._handle.setBlocking(true);
if (process.stderr._handle) process.stderr._handle.setBlocking(true);

As far as I know, the above should tell the function that emits to stdout to become blocking and avoid buffering, which might bypass the issue you're seeing.

Alternatively, have you considered adopting the log buffering feature of Logger? Using that would allow you to control when the buffer is flushed, which might also help.

[slewis77]

Hi @dreamorosi ,

Below is the approach I took to work around the issue (just for the logs that cause the buffering), which is what I meant by wrapping in a promise. The stream write has an optional callback to tell you when the write has completed, we use that to resolve a promise wrapped around the call. I think Logger uses a Console instance, which wraps the calls to stdout, which I don't think exposes the callback.

export const logSomething = ({
  something,
  timestamp,
  xrayTraceId,
}: {
  something: Record<string, unknown>;
  timestamp: number | undefined;
  xrayTraceId: string | undefined;
}): Promise<void> =>
  new Promise((resolve, reject) => {
    const success = process.stdout.write(
      JSON.stringify({
        level: 'INFO',
        message: 'example',
        timestamp,
        service: 'example-service',
        xray_trace_id: xrayTraceId,
        something,
      }) + '\n',
      (error) => {
        if (success) {
          // Avoid resolving again
          return;
        }

        if (error) {
          reject(error);
        } else {
          resolve();
        }
      },
    );

    // If write returns true, it was written immediately (buffer not full)
    if (success) {
      resolve();
    }
  });

I think you're right that the Logger buffering could have helped, but it then becomes a problem knowing the sweet spot for how much to buffer to not still accidentally trigger the problem

[dreamorosi]

Thanks, that helps.

I don't know if we'll be able to make this kind of change, since it'd make all logging operations asynchronous, but I understand losing data is also not ideal - unsure if this is something we can impact.

You're right that our logger uses an instance of Console under the hood, because of this, I think the lines that I suggested above and that change the behavior of how the stdout is handled might help.

Any chance you could give these a try?

[slewis77]

Hi,

Just tried setBlocking(true)

What I found is, firstly, it works reliably, I didn't lose any logs.

However, it is overall slower than allowing it to buffer and using the callback to make sure it has finished. In my crude testing about twice as slow (worked out to roughly 20 seconds slower writing about 50,000 items)

[dreamorosi]

Hi, thanks for testing so quickly.

I think that's expected, you're trading off overall duration for making sure that every single log is flushed as soon as it's emitted.

I don't know if we can have both in this environment to be honest.