Bref: Unrecoverable state on Socket Exception

[atrope]

When Lambda enters in the catch section of the responder exception, it will never recover until AWS decides to kill it.

        try {
            $responder->send($requestHeaders, $requestBody);
        } catch (HoaFastCgiException|HoaSocketException $e) {
}

I am investigating what we can do in order to fix this issue.

I Already tried:

1 - killExistingFpm - it does kill, but the process stays as defunct and waitUntilStopped always return timeout error exception.
2 - killExistingFpm removing the waitUntilStopped, this "works" as fpm again loads, but the socket never attach to it..
3 - used shell_exec to kill the process and results the same as 1

Will update here when I have more results.. Feel free to drop your penny here.

[mnapoli]

Thanks for the report. FYI there were 2 recent releases trying to address timeouts like these (and recovering from them): https://github.com/mnapoli/bref/releases It might be worth to check those pull requests.

Could you make sure you are using the latest Bref version as well as the latest runtimes? (https://runtimes.bref.sh/)

[atrope]

Hi @mnapoli i did, killExistingFpm was added in #272.
The runtime i am using ours(we need custom extensions), but with the latest code

[mnapoli]

👍

The runtime i am using ours(we need custom extensions), but with the latest code

FYI you can use Bref's official layers and only add your compiled extension via an additional layers (but maybe that's already what you are doing).

[atrope]

@mnapoli most extensions yes, but i need to have PHP compiled with SOAP support (google ads sdk) and redis compiled with igbinary support also, with this i need to have my own runtime running ( i could only overwrite those files, but i think its easier having everything in a single layer)

[atrope]

Fatal error: Uncaught Bref\Runtime\FastCgiCommunicationFailed: Error communicating with PHP-FPM to read the HTTP response. A common root cause of this can be that the Lambda (or PHP) timed out, for example when trying to connect to a remote API or database, if this happens continuously check for those! Bref will reconnect to PHP-FPM to clean things up. Original exception message: Hoa\Fastcgi\Exception\Exception Bad request (not a well-formed FastCGI request). in /opt/var/task/app/library/vendor/mnapoli/bref/src/Runtime/PhpFpm.php:120
Stack trace:
#0 /opt/bootstrap(33): Bref\Runtime\PhpFpm->proxy(Array)
#1 /opt/var/task/app/library/vendor/mnapoli/bref/src/Runtime/LambdaRuntime.php(58): {closure}(Array)
#2 /opt/bootstrap(37): Bref\Runtime\LambdaRuntime->processNextEvent(Object(Closure))

Thats the error that gives me.

@mnapoli do you know if i can kill a lambda to force AWS to create a new one?

[mnapoli]

@atrope I tried before and didn't manage to do it, the only way I succeeded was redeploying (with a change! else cloudformation doesn't update the lambda).

Also do you get this exception in a loop? What happens after that? By the way do you know what causes the communication to fail in the first place?

[atrope]

Redeploying does not work for us.

@mnapoli yes, I tried also to do it in a loop and it always timesout trying to do the request.

I Also tried to check if the error was indeed on the request, but the same request - Headers and Body - would sometimes fail. So i ruled out the possibility of eventToFastCgiRequest sending something invalid

[atrope]

Ok more insights..

[18-Mar-2019 15:11:19] NOTICE: fpm is running, pid 9
[18-Mar-2019 15:11:19] NOTICE: ready to handle connections
START RequestId: 0786516c-6853-47c0-a90e-953d84185929 Version: $LATEST
END RequestId: 0786516c-6853-47c0-a90e-953d84185929
REPORT RequestId: 0786516c-6853-47c0-a90e-953d84185929  Init Duration: 581.29 ms    Duration: 820.43 ms Billed Duration: 1500 ms Memory Size: 704 MB    Max Memory Used: 88 MB  
START RequestId: e855a430-023c-4396-a6c7-d0d70b974430 Version: $LATEST
Fatal error: Hoa\Fastcgi\Exception\Exception: Bad request (not a well-formed FastCGI request). in /opt/var/task/app/library/vendor/hoa/fastcgi/Responder.php:239
Stack trace:
#0 /opt/var/task/app/library/vendor/mnapoli/bref/src/Runtime/PhpFpm.php(115): Hoa\Fastcgi\Responder->send(Array, '')
#1 /opt/bootstrap(33): Bref\Runtime\PhpFpm->proxy(Array)
#2 /opt/var/task/app/library/vendor/mnapoli/bref/src/Runtime/LambdaRuntime.php(58): {closure}(Array)
#3 /opt/bootstrap(37): Bref\Runtime\LambdaRuntime->processNextEvent(Object(Closure))
#4 {main}[18-Mar-2019 15:11:20] WARNING: [pool default] child 10 exited on signal 4 (SIGILL) after 0.979374 seconds from start
[18-Mar-2019 15:11:20] NOTICE: [pool default] child 13 started
[18-Mar-2019 15:11:20] NOTICE: Terminating ...
[18-Mar-2019 15:11:20] NOTICE: exiting, bye-bye!
END RequestId: e855a430-023c-4396-a6c7-d0d70b974430
REPORT RequestId: e855a430-023c-4396-a6c7-d0d70b974430  Duration: 247.49 ms Billed Duration: 300 ms Memory Size: 704 MB Max Memory Used: 88 MB  
RequestId: e855a430-023c-4396-a6c7-d0d70b974430 Error: Runtime exited with error: exit status 1
Runtime.ExitError
[18-Mar-2019 15:11:21] NOTICE: fpm is running, pid 8
[18-Mar-2019 15:11:21] NOTICE: ready to handle connections
START RequestId: ea9a3a58-64ca-45ed-b082-20e8e55445c1 Version: $LATEST
Fatal error: Hoa\Fastcgi\Exception\Exception: Bad request (not a well-formed FastCGI request). in /opt/var/task/app/library/vendor/hoa/fastcgi/Responder.php:239
Stack trace:
#0 /opt/var/task/app/library/vendor/mnapoli/bref/src/Runtime/PhpFpm.php(115): Hoa\Fastcgi\Responder->send(Array, '')
#1 /opt/bootstrap(33): Bref\Runtime\PhpFpm->proxy(Array)
#2 /opt/var/task/app/library/vendor/mnapoli/bref/src/Runtime/LambdaRuntime.php(58): {closure}(Array)
#3 /opt/bootstrap(37): Bref\Runtime\LambdaRuntime->processNextEvent(Object(Closure))
#4 {main}[18-Mar-2019 15:11:21] NOTICE: Terminating ...
[18-Mar-2019 15:11:21] NOTICE: exiting, bye-bye!
END RequestId: ea9a3a58-64ca-45ed-b082-20e8e55445c1
REPORT RequestId: ea9a3a58-64ca-45ed-b082-20e8e55445c1  Duration: 475.03 ms Billed Duration: 500 ms Memory Size: 704 MB Max Memory Used: 81 MB  
RequestId: ea9a3a58-64ca-45ed-b082-20e8e55445c1 Error: Runtime exited with error: exit status 1
Runtime.ExitError

Even when fpm is exited and i get it running with another pid it does not recover.. will continue with tests and will update here.

[atrope]

More updates:
The error happens when
stream_socket_recvfrom is returning false on /hoa/socket/Connection/Connection.php .

I've found this thread from 2011: https://bugs.php.net/bug.php?id=55814

There it is saying that if we set the stream_set_blocking($client, true); it should work.

I did that and edited the part that deals with this on our case:

        if (false === $this->isRemoteAddressConsidered()) {
            stream_set_blocking($this->getStream(), true);
            return stream_socket_recvfrom($this->getStream(), $length, $flags);
        }

And still is giving us errors.
The client is reporting to still be connected even with the errors.

My question now is, if there is a way for us to check if the socket is still in a state where it can be used or not.

I Want to check if the root of our problems is the socket or any other part.

[mnapoli]

This might be worth asking at https://github.com/hoaproject/Fastcgi which is the library we use internally. Also if can explain a minimal setup to reproduce this, I'd love to help.

[atrope]

@mnapoli I don't know how to reproduce it, i think its just a matter of quantity, because the same request can fail or succeed, as it is written in the php bug issue, it seem random

[atrope]

Ok Some update..

While i'm still not able to fix the issue, i think i got to a viable workaround at the moment..

I save the uri the user was trying to get to (with the querystring) and i make a 307 redirect (that way, the browser, or the API requester would also forward any POST request with its body to the "new URL", that way the new redirect will almost certain get to a working lambda and will return as planned to our user.

try {
            $responder->send($requestHeaders, $requestBody);
        } catch (HoaFastCgiException|HoaSocketException $e) {
            // Once the socket gets broken every following request is broken. We need to reconnect.
              $this->reconnect();
              $headerserror =["x-powered-by"=> ["PHP/7.2.15"],"Location"=>[$this->uri],"cache-control"=> ["no-store, no-cache, must-revalidate"],"pragma"=> ["no-cache"],"content-type"=> ["text/html; charset=UTF-8"]];
              return new LambdaResponse(307, $headerserror, "");
        }

The no-cache is really important to override if we use CF in front of our service to make sure it will not cache this broken response.

I Will update later with the performance of this workaround

[mnapoli]

FYI because of this issue and #316 we had a look at changing the underlying library to deal with FastCGI (in https://github.com/mnapoli/bref/tree/replace-fastcgi-library). That solved #316 (or at least it solved the test that reproduced it), hopefully this should help here as well.

[mnapoli]

Here is the PR: #319 Hopefully that fixes this issue.

[atrope]

@mnapoli will check what you've done and will update here!

[atrope]

@mnapoli 2 updates.

1 - With hollodotme/fast-cgi-client (the one i used before) we will be able to close #263 because i can parse the Multi-Value headers getting the Raw Response from the library.
As soon as i have some time i will update the PR.

2 - Unfortunately it did not work for the problem in this thread.. As soon as i deployed, it started firing 502s https://prnt.sc/ngvtrc .
I will dig further now with hollodotme and see if i can find any other root of this problem..

[atrope]

Just documenting it here, with hollodotme the error is coming from
private function handleNullPacket( ?array $packet ) : void

if ( $info['unread_bytes'] === 0 && $info['blocked'] && $info['eof'] ){
    throw new ReadFailedException( 'Stream got blocked, or terminated.' );
}

it does looks like the same, or similar, exception that hoa was firing.
the packet is returning null with the stream reporting no new bytes to read.

[hollodotme]

@atrope This exception is raised when the underlying stream gets terminated externally while the response is read, e.g. by killing the php-fpm (pool) process. I just reassured myself by running a worker and killing php-fpm after I sent the request. There is nothing the library could actually do in such a case other than reporting the broken stream through an exception. Anyway, in case the php-fpm is not fully down issuing a new request should work and the client establishes a new connection to php-fpm.

[hollodotme]

@atrope Update: I just found a scenario where the previously mentioned failed socket connection is not removed from the internal collection of the client and can cause an infinite loop waiting for a response on that failed connection. I'm about to fix this in v2.7.1, but I'm not sure, if this will fix this issue in general.

[hollodotme]

@atrope I just released v2.7.1.

[atrope]

@mnapoli
Today i was all day trying to check the performance issues that we talked about and in the process i connected the dots between this error and #275 and why it was only happening to me.

I Was able to upload the core dumps files to S3 and found out that the dumps were SIGILL and the errors were being caused by a PHP extension that was firing an unknown instruction for lambda CPU because it was compiled in the lambda env but in my computer.

I generated a new layer with all the extensions compiled in a m4 machine (Intel XEON) and then the Socket errors Are finally (for the last 20 minutes) gone!

So IMO this issue is not a real issue and we can close it. :pray:

I Will now investigate the performance issues without this error :)

[mnapoli]

Oh this is awesome!