AWS CloudWatch not capturing Log::error() for Lambda functions which time out

Question

I have a simple Laravel app using AWS Lambda functions. I am trying to debug why lambda times out sometimes, so I am logging one of the HTTP request parameters in the controller. But the issue is that the logs don't get recorded to CloudWatch when lambda times out. Why?

I log like this:

class ExchangeController extends Controller {
    function balance(Request $request) {
        Log::info("[ExchangeController] Start: " . $request->exchange . ", " . $_ENV['AWS_REQUEST_ID']);
        $request->process();
        Log::info("[ExchangeController] OK ");
        ...

Here you can see example of "Task timed out" log, as you can see there is no sign of my Log::info() output:

but in the case of non timed out function, my logs work just fine:

Answer 1

I'm not a Laravel coder, but in my experience with other languages, when a Lambda function times out, it is HARD-STOPPED. Execution flow seems to be aborted entirely - this includes any kind of last-gasp error handling/reporting or context-unraveling code that you might expect to run after a normal error. It's like someone pulled the plug out of the wall.

If you want to log the input, you need to log the input immediately on entry into the handler, and not as part of anything that is promised to complete later, because in the event of a timeout, later may not come.

Answer 2

I was able to find a workaround, but it's not ideal; I am now logging synchronously using a 3rd party log API (https://docs.newrelic.com/docs/logs/log-api/introduction-log-api/, it's free), by simply making a http post request like so:

Http::post("https://log-api.eu.newrelic.com/log/v1?Api-Key=yourkey",
    [ "message" => 
        "[ExchangeController] Start [" . $request->exchange . (isset($_ENV['AWS_REQUEST_ID']) ? ", " . $_ENV['AWS_REQUEST_ID'] : "") . "]"
    ]);

I can now finally see which request parameters are causing timeouts. The downside is that synchronous logging is probably not a good idea, as it slows down execution and is depending on external API response time. But nonetheless, I just need it to debug the root issue, and will remove it later.