Handle timeouts more gracefully by allowing the application to shutdown

[Nyholm]

This PR builds on the work started by @t-geindre in #55.

If we are 1 second away from Lambda shutting down, then thrown an exception to let the application shutdown and (more importantly) flush the logs.

There are two things Im not super happy with:

1. This does not work for PHP-FPM since it the application run in a child process
2. I get a segmentation fault when SIGALRM is triggers while the application is waiting for IO (https://bugs.php.net/bug.php?id=80907)

The question is: do we want to continue down this path?

It would solve issues like #873 and #862.

TODO

• Add docs
• Do some manual testing to make sure this works as expected

[deleugpn]

I get a segmentation fault when SIGALRM is triggers while the application is waiting for IO

Isn't every connection timeout an IO operation that PHP is waiting?

This does not work for PHP-FPM since it the application run in a child process

This seems to me like a strong enough limitation that may indicate it's not worth it to support it? It does bring a nice idea to the table though: what if we offer a Debugging Layer where you can write a basic function invocation and run the code that's getting timeout from it so that you might get a better idea where it's stopping?
By making it an explicit debugging layer, we don't need to guarantee production-ready quality and perhaps we can even try to include default debugging statements that will get logged? In the end people will use this in order to figure out why their Lambda can't connect somewhere (VPC, Firewall, Security Group, NAT Gateway, Internet Gateway, NACL, etc) which has nothing to do with the code itself.

[mnapoli]

Hey, I wonder if something similar could be used in the PHP-FPM worker (the process handling the request)?

That could be done as a Symfony/Laravel package?

I'm not familiar enough with signals like that to know if that could work.

Also another solution is to find a way for logs to be streamed correctly. Or else, find a way to force shorter timeouts on all connections in all frameworks, but I have no idea if that's even remotely possible.

[Nyholm]

Isn't every connection timeout an IO operation that PHP is waiting?

Yeah.. Each curl request, file load or sleep is IO operations. But this is a PHP bug that I assume will be fixed soon. (I updated the PR description with a bug report).

This seems to me like a strong enough limitation that may indicate it's not worth it to support it

Im not sure.. I strongly believe in a future were all PHP applications are using a runtime. See #889.

I wonder if something similar could be used in the PHP-FPM worker

Probably, yes.

That could be done as a Symfony/Laravel package?

Yes, it is called runtime/bref =)

Also another solution is to find a way for logs to be streamed correctly.

I dont think that is possible. Or.. there is a difference between application logs and FPM logs. For the FPM logs => I have no idea.
For the application logs: Monolog buffers the logs and we need to tell the logger to flush the buffer (ie, destruct the logger). So it needs an exception to be thrown.

Debug layer

I like the idea, But it does not solve the problem where 1/10000 request to my live application times out and I want to find out what happens. If the "debug layer" is not production ready, the I would not be happy adding it to my production environment.

[Nyholm]

I reorganized things.

I've updated LambdaRuntime to get a bool parameter to enable throwing TimeoutException. This is enabled in the bootstrap files in php-xx and console. It is not enabled in the php-fpm. For FPM the user needs to update their application by adding Bref\Timeout\Timeout::enable(). This will read the environment variables and set the timeout.

I think this is a good way forward. I would like to get another review before I add tests and docs.

[Nyholm]

You may also control this behavior with BREF_TIMEOUT.
Value 0 is "auto". Value "-1" is disabled. Positive values sets the timeout.

[Nyholm]

A PHP-FPM user would have to write something like:

if (isset($_SERVER['LAMBDA_TASK_ROOT'])) {
    Bref\Timeout\Timeout::enable();
}

Preferably as soon as possible, ie Kernel::handle() or index.php.

[mnapoli]

Thanks, following our discussions I've opened Nyholm#3 to remove the option of configuring the duration timeout via an environment variable.

[Nyholm]

The support PR is merged. This PR is now ready for a final rounds of review.

[Nyholm]

Im 👍

We don't mention that the logs from php-fpm also will be flushed, but that is a technical detail I think it is okey to skip.

[mnapoli]

Should we force a 500 status code before exit?

That would only be taken into account in the FPM layer, so that wouldn't really impact the php-XX layer.

[Nyholm]

How?
And wouldn't that effect my AWS::ApiGateway::GatewayResponse that triggers on timeouts or 500?

[mnapoli]

http_response_code(500);

And wouldn't that effect my AWS::ApiGateway::GatewayResponse that triggers on timeouts or 500?

🤔 not sure about that, maybe. But in any case, the same would happen if your app returns a pretty 500 error page.

Does that make sense? What I mean is that, when using FPM, there would be no difference between:

• Symfony catches any exception and displays an error page with a 500 status code
• Bref timeout kicks in and forces a 500 status code

In both cases, API Gateway would behave the same way.

[Nyholm]

Oh, no that is not true.

Symfony catches any exception and displays an error page with a 500 status code

This will show you a nice error page. API Gateway does nothing

Bref timeout kicks in and forces a 500 status code

No content(HTML) is provided. I would like the custom error page in API Gateway to be used.

---

Im not sure if http_response_code(500) would make any difference.

---

Also note. We are not sure it is a HTTP context. It could be any other event.. So Im not sure about sending a HTTP status code.

[mnapoli]

For the record, I'm testing and notice that error_log adds noise in FPM:

NOTICE: PHP message: Lambda timed out
NOTICE: PHP message: #0 /var/task/demo/http.php(16): Bref\Timeout\Timeout::Bref\Timeout\{closure}()
#1 {main}
NOTICE: PHP message: Original stack trace
NOTICE: PHP message: #0 /var/task/demo/http.php(9): Bref\Timeout\Timeout::Bref\Timeout\{closure}()
#1 {main}

I'm changing that to:

                $stderr = fopen('php://stderr', 'w');
                fwrite($stderr, 'Lambda timed out' . PHP_EOL);
                fwrite($stderr, (new LambdaTimeout)->getTraceAsString() . PHP_EOL);
                fwrite($stderr, 'Original stack trace' . PHP_EOL);
                fwrite($stderr, Timeout::$stackTrace . PHP_EOL);
                fclose($stderr);

Which gives a cleaner log:

Lambda timed out
#0 /var/task/demo/http.php(16): Bref\Timeout\Timeout::Bref\Timeout\{closure}()
#1 {main}
Original stack trace
#0 /var/task/demo/http.php(9): Bref\Timeout\Timeout::Bref\Timeout\{closure}()
#1 {main}

No need to update the PR

[Nyholm]

Oh, I didnt know.

Thank you for testing.

[mnapoli]

OK following discussion through Slack, we were happy with the PR.

However I tested and I'm getting weird results in FPM too:

• 1st request: the timeouts work as expected
• following requests: pcntl_alarm(...) is triggered, but our custom handler isn't called. That causes pending I/O (or sleep) to be interrupted, but without any exception being triggered

I've been testing locally with PHP-FPM to pinpoint this, but my guess currently is that pcntl signals may not work well with FPM and its worker pool. Maybe we first set a signal handler on the process, and it's not correctly cleaned up by FPM on the next request cycle?

I tried cleaning up manually the handlers, no changes. I tried putting the cleanup in a __destruct() to be sure it's executed, no changes. I'm not sure what to do anymore…

How to reproduce locally:

• docker-compose up
• add \Bref\Timeout\Timeout::enableInFpm(); at the top of demo/http.php
• open http://localhost:8000/?sleep=1
• play with demo/http.php in the sleep block (e.g. catch the exception)

E.g. in my case:

if (isset($_GET['sleep'])) {
    echo 'Sleeping';
    try {
        sleep(6);
    } catch (Throwable $e) {
        echo 'CAUGHT!';
    }
    echo 'Sleeping';
    sleep(2);
}

• first request: I see CAUGHT!
• next requests: the catch is not executed, yet the sleep() calls are interrupted (without errors/warnings)

[mnapoli]

Since this wasn't working with FPM I went with a different route: #1133

This PR might still be worth following for the Function layer, so I'll leave it open.