Repository: brefphp/bref (language: php)

Issue:
Logging to stderr has some kind of limit in the PHP-FPM runtime
**Description:**
It seems that logging to stderr with monolog (using Symfony 6.3) has some kind of limit in the web function, with php-fpm runtime.
Whenever some threshold in amount (and size) of log entries is reached the lambda seems to hang until it times out after 28 seconds. 

For instance we have an import endpoint which reads an uploaded Excel sheet. With logging enabled we can process about 260 rows before it hangs. The same command for processing but then run via a console command has no issue whatsoever, it handles 13.000+ rows easily. Also worker lambdas do not show this behavior

This behavior is also observed locally with the same runtime.

**Debgging steps tried:**
When minimum log level is raised to notice, the logging is reduced to next to nothing (only when an unhandled exception or a PHP notice/warning/error occurs it will be logged). In this case importing via web request works even for 13.000 rows, with only 1 or 2 seconds to spare before the 28 second timeout.
I've also tried increasing memorySize to no effect. No difference noticed comparing 1792M, 10240M and the default 1024M (which we normally use).

**How to reproduce:**
Attached a Symfony controller and a console command to test amount of log entries (on top of entries generated by frameork and dependencies).
[source.zip](https://github.com/brefphp/bref/files/13904299/source.zip)
- Create a simple Symfony (6.3) project with monolog and add the controller and command.
- Add and setup Bref (2.1.3)
- Setup serverless.yml with the runtimes (web: php-82-fpm, console: php-82-console, worker: php-82)
- Use a local docker setup with web php image bref/php-82-fpm-dev:2

See also Slack: https://brefworkspace.slack.com/archives/C057S6G4Z9N/p1704917185595609


Discussion / hints:
I was having this issue with symfony deprecation logs
When lot of deprecations are triggered, lambda hangs until timeout (28 seconds) is reached.
@kevincerro I assume you 'solved' it by disabling deprecation logging.
> @kevincerro I assume you 'solved' it by disabling deprecation logging.

I fixed the deprecation (was being triggered multiple times inside a for loop)

But yes, disabling deprecation logger was my alternative hotfix.
Pasting my comment from Slack here for reference:

FYI FPM logs are forwarded to CloudWatch via this: https://github.com/brefphp/bref/blob/master/src/FpmRuntime/FpmHandler.php#L82-L85 

Something could be "overwhelming" the PHP code here?

Or maybe it could be this config option for the FPM configuration: https://github.com/brefphp/aws-lambda-layers/blob/main/layers/fpm/php-fpm.conf#L9-L10
I've tried with different FPM config values, to no effect.

- log_limit to ten times 8192
- log_buffering = no

Also tested with php-fpm-83. No luck 🤷🏻‍♂️ 


Fix patch:
diff --git a/src/FpmRuntime/FpmHandler.php b/src/FpmRuntime/FpmHandler.php
index 6f7136184..caa1ef145 100644
--- a/src/FpmRuntime/FpmHandler.php
+++ b/src/FpmRuntime/FpmHandler.php
@@ -15,7 +15,7 @@
 use hollodotme\FastCGI\Interfaces\ProvidesRequestData;
 use hollodotme\FastCGI\Interfaces\ProvidesResponseData;
 use hollodotme\FastCGI\SocketConnections\UnixDomainSocket;
-use Symfony\Component\Process\Process;
+use RuntimeException;
 use Throwable;
 
 /**
@@ -47,7 +47,8 @@ final class FpmHandler extends HttpHandler
     private UnixDomainSocket $connection;
     private string $handler;
     private string $configFile;
-    private ?Process $fpm = null;
+    /** @var resource|null */
+    private $fpm;
 
     public function __construct(string $handler, string $configFile = self::CONFIG)
     {
@@ -76,13 +77,12 @@ public function start(): void
          * --nodaemonize: we want to keep control of the process
          * --force-stderr: force logs to be sent to stderr, which will allow us to send them to CloudWatch
          */
-        $this->fpm = new Process(['php-fpm', '--nodaemonize', '--force-stderr', '--fpm-config', $this->configFile]);
+        $resource = @proc_open(['php-fpm', '--nodaemonize', '--force-stderr', '--fpm-config', $this->configFile], [], $pipes);
 
-        $this->fpm->setTimeout(null);
-        $this->fpm->start(function ($type, $output): void {
-            // Send any PHP-FPM log to CloudWatch
-            echo $output;
-        });
+        if (! is_resource($resource)) {
+            throw new RuntimeException('PHP-FPM failed to start');
+        }
+        $this->fpm = $resource;
 
         $this->client = new Client;
         $this->connection = new UnixDomainSocket(self::SOCKET, 1000, 900000);
@@ -95,12 +95,11 @@ public function start(): void
      */
     public function stop(): void
     {
-        if ($this->fpm && $this->fpm->isRunning()) {
+        if ($this->isFpmRunning()) {
             // Give it less than a second to stop (500ms should be plenty enough time)
             // this is for the case where the script timed out: we reserve 1 second before the end
             // of the Lambda timeout, so we must kill everything and restart FPM in 1 second.
-            // Note: Symfony will first try sending SIGTERM (15) and then SIGKILL (9)
-            $this->fpm->stop(0.5);
+            $this->stopFpm(0.5);
             if ($this->isReady()) {
                 throw new Exception('PHP-FPM cannot be stopped');
             }
@@ -192,7 +191,7 @@ public function handleRequest(HttpRequestEvent $event, Context $context): HttpRe
      */
     private function ensureStillRunning(): void
     {
-        if (! $this->fpm || ! $this->fpm->isRunning()) {
+        if (! $this->isFpmRunning()) {
             throw new Exception('PHP-FPM has stopped for an unknown reason');
         }
     }
@@ -215,8 +214,9 @@ private function waitUntilReady(): void
             }
 
             // If the process has crashed we can stop immediately
-            if (! $this->fpm->isRunning()) {
-                throw new Exception('PHP-FPM failed to start: ' . PHP_EOL . $this->fpm->getOutput() . PHP_EOL . $this->fpm->getErrorOutput());
+            if (! $this->isFpmRunning()) {
+                // The output of FPM is in the stderr of the Lambda process
+                throw new Exception('PHP-FPM failed to start');
             }
         }
     }
@@ -337,4 +337,37 @@ private function getResponseHeaders(ProvidesResponseData $response): array
     {
         return array_change_key_case($response->getHeaders(), CASE_LOWER);
     }
+
+    public function stopFpm(float $timeout): void
+    {
+        if (! $this->fpm) {
+            return;
+        }
+
+        $timeoutMicro = microtime(true) + $timeout;
+        if ($this->isFpmRunning()) {
+            $pid = proc_get_status($this->fpm)['pid'];
+            // SIGTERM
+            @posix_kill($pid, 15);
+            do {
+                usleep(1000);
+                // @phpstan-ignore-next-line
+            } while ($this->isFpmRunning() && microtime(true) < $timeoutMicro);
+
+            // @phpstan-ignore-next-line
+            if ($this->isFpmRunning()) {
+                // SIGKILL
+                @posix_kill($pid, 9);
+                usleep(1000);
+            }
+        }
+
+        proc_close($this->fpm);
+        $this->fpm = null;
+    }
+
+    private function isFpmRunning(): bool
+    {
+        return $this->fpm && proc_get_status($this->fpm)['running'];
+    }
 }


Test patch:
diff --git a/tests/FpmRuntime/FpmHandlerTest.php b/tests/FpmRuntime/FpmHandlerTest.php
index 1515150f6..9ae4e7ce0 100644
--- a/tests/FpmRuntime/FpmHandlerTest.php
+++ b/tests/FpmRuntime/FpmHandlerTest.php
@@ -1254,8 +1254,9 @@ public function test worker logs are still written in case of a timeou
             ], new Context('abc', time(), 'abc', 'abc'));
             $this->fail('No exception was thrown');
         } catch (Timeout $e) {
-            $logs = ob_get_contents();
-            self::assertStringContainsString('This is a log message', $logs);
+            $this->markTestSkipped('We can no longer test this since proc_open skips output buffering, we cannot capture the logs');
+//            $logs = ob_get_contents();
+//            self::assertStringContainsString('This is a log message', $logs);
         }
     }
 
@@ -1285,6 +1286,16 @@ public function test warmer events do not invoke the application()
         self::assertEquals(['Lambda is warm'], $result);
     }
 
+    /**
+     * @see https://github.com/brefphp/bref/issues/1369
+     */
+    public function test large logs()
+    {
+        $response = $this->get('large-logs.php');
+
+        self::assertSame('Hello, world!', $response['body']);
+    }
+
     private function assertGlobalVariables(array $event, array $expectedGlobalVariables): void
     {
         $this->startFpm(__DIR__ . '/fixtures/request.php');
diff --git a/tests/FpmRuntime/fixtures/large-logs.php b/tests/FpmRuntime/fixtures/large-logs.php
new file mode 100644
index 000000000..154ebd984
--- /dev/null
+++ b/tests/FpmRuntime/fixtures/large-logs.php
@@ -0,0 +1,7 @@
+<?php declare(strict_types=1);
+
+$stderr = fopen('php://stderr', 'wb');
+$bytes = 512 * 512;
+fwrite($stderr, str_repeat('x', $bytes));
+
+echo 'Hello, world!';
diff --git a/tests/FpmRuntime/fixtures/php-fpm.conf b/tests/FpmRuntime/fixtures/php-fpm.conf
index de1f6759f..9c4420d63 100644
--- a/tests/FpmRuntime/fixtures/php-fpm.conf
+++ b/tests/FpmRuntime/fixtures/php-fpm.conf
@@ -3,6 +3,9 @@ error_log = /dev/null
 ; Log above warning because PHP-FPM logs useless notices
 ;log_level = 'warning'
 
+; New PHP 7.3 option that includes the maximum length when writing to stderr
+log_limit = 8192
+
 [default]
 pm = static
 ; We only need one child because a lambda can process only one request at a time
@@ -13,8 +16,7 @@ clear_env = yes
 ; Forward stderr of PHP processes to stderr of PHP-FPM (so that it can be sent to cloudwatch)
 catch_workers_output = yes
 ; New PHP 7.3 option that disables a verbose log prefix
-; Disabled for now until we switch to PHP 7.3
-;decorate_workers_output = no
+decorate_workers_output = no
 ; Limit the number of core dump logs to 1 to avoid filling up the /tmp disk
 ; See https://github.com/brefphp/bref/issues/275
 rlimit_core = 1