Merge pull request #4 from kodus/server-log

Server log

Author: mindplay-dk

README.md

@@ -11,6 +11,8 @@ Alternative to the original [ChromeLogger](https://craig.is/writing/chrome-logge
  * [PSR-7](http://www.php-fig.org/psr/psr-7/) HTTP message abstraction for the models, and
  * [PSR-15](https://www.php-fig.org/psr/psr-15/) compliant middleware for quick integration.
 
+✨ An alternative to the ChromeLogger extension [is also available](http://github.com/kodus/server-log)
+and is [highly recommended](#header-size-limit).
 
 ## Usage
 
@@ -22,6 +24,8 @@ $logger = new ChromeLogger();
 $logger->notice("awesome sauce!");
 ```
 
+Note that this will have a [header-size limit](#header-size-limit) by default.
+
 Using a PSR-7 compliant `ResponseInterface` instance, such as in a middleware stack, you can populate
 the Response as follows:
 
@@ -69,11 +73,26 @@ try {
 Any PHP values injected via the context array will be serialized for client-side inspection - including complex
 object graphs and explicit serialization of problematic types like `Exception` and `DateTime`.
 
+
+<a name="header-size-limit"></a>
 ### Header Size Limit
 
-Note that [Chrome has a 250KB header size limit](https://cs.chromium.org/chromium/src/net/http/http_stream_parser.h?q=ERR_RESPONSE_HEADERS_TOO_BIG&sq=package:chromium&dr=C&l=159),
-which we have to respect - due to this fact, the beginning of the log may get truncated, if the header-size is above
-a set limit, which by default is 240KB. You can change this limit using the `ChromeLogger::setLimit()` method.
+[Chrome has a 250KB header size limit](https://cs.chromium.org/chromium/src/net/http/http_stream_parser.h?q=ERR_RESPONSE_HEADERS_TOO_BIG&sq=package:chromium&dr=C&l=159)
+and many popular web-servers (including NGINX and Apache) also have a limit.
+
+By default, the beginning of the log will be truncated to keep the header size under the limit.
+
+You can change this limit using the `ChromeLogger::setLimit()` method - but a better approach is
+to enable logging to local files, which will persist in a web-accessible folder for 60 seconds:
+
+```php
+$logger->usePersistence("/var/www/mysite/webroot/logs", "/logs");
+```
+
+Note that this isn't supported by the ChromeLogger extension - you will need to install the alternative
+[Server Log Chrome extension](http://github.com/kodus/server-log) instead. (It is backwards
+compatible with the header-format of the original ChromeLogger extension, so you can use this as
+a drop-in replacement for the original extension.)
 
 
 ## Limitations

src/ChromeLogger.php

@@ -5,6 +5,8 @@
 use DateTimeInterface;
 use Error;
 use Exception;
+use function file_put_contents;
+use InvalidArgumentException;
 use JsonSerializable;
 use Psr\Http\Message\ResponseInterface;
 use Psr\Log\AbstractLogger;
@@ -31,6 +33,7 @@ class ChromeLogger extends AbstractLogger implements LoggerInterface
     const CLASS_NAME  = "type";
     const TABLES      = "tables";
     const HEADER_NAME = "X-ChromeLogger-Data";
+    const LOCATION_HEADER_NAME = "X-ServerLog-Location";
 
     const LOG   = "log";
     const WARN  = "warn";
@@ -56,6 +59,16 @@ class ChromeLogger extends AbstractLogger implements LoggerInterface
      */
     protected $entries = [];
 
+    /**
+     * @var string|null
+     */
+    private $local_path;
+
+    /**
+     * @var string|null
+     */
+    private $public_path;
+
     /**
      * Logs with an arbitrary level.
      *
@@ -92,6 +105,32 @@ public function getLimit()
         return $this->limit;
     }
 
+    /**
+     * Enables persistence to local log-files served from your web-root.
+     *
+     * Bypasses the header-size limitation (imposed by Chrome, NGINX, etc.) by avoiding the
+     * large `X-ChromeLogger-Data` header and instead storing the log in a flat file.
+     *
+     * Requires the [ServerLog](https://github.com/mindplay-dk/server-log) Chrome extension,
+     * which replaces the ChromeLogger extension - this does NOT work with the regular
+     * ChromeLogger extension.
+     *
+     * @link https://github.com/mindplay-dk/server-log
+     *
+     * @param string $local_path  absolute local path to a dedicated log-folder in your public web-root,
+     *                            e.g. "/var/www/mysite.com/webroot/log"
+     * @param string $public_path absolute public path, e.g. "/log"
+     */
+    public function usePersistence(string $local_path, string $public_path)
+    {
+        if (! is_dir($local_path)) {
+            throw new InvalidArgumentException("local path does not exist: {$local_path}");
+        }
+
+        $this->local_path = $local_path;
+        $this->public_path = $public_path;
+    }
+
     /**
      * Adds headers for recorded log-entries in the ChromeLogger format, and clear the internal log-buffer.
      *
@@ -104,11 +143,15 @@ public function getLimit()
      */
     public function writeToResponse(ResponseInterface $response)
     {
-        $value = $this->getHeaderValue();
+        if ($this->local_path) {
+            $response = $response->withHeader(self::LOCATION_HEADER_NAME, $this->createLogFile());
+        } else {
+            $response = $response->withHeader(self::HEADER_NAME, $this->getHeaderValue());
+        }
 
         $this->entries = [];
 
-        return $response->withHeader(self::HEADER_NAME, $value);
+        return $response;
     }
 
     /**
@@ -126,7 +169,11 @@ public function emitHeader()
             throw new RuntimeException("unable to emit ChromeLogger header: headers have already been sent");
         }
 
-        header(self::HEADER_NAME . ": " . $this->getHeaderValue());
+        if ($this->local_path) {
+            header(self::LOCATION_HEADER_NAME . ": " . $this->createLogFile());
+        } else {
+            header(self::HEADER_NAME . ": " . $this->getHeaderValue());
+        }
 
         $this->entries = [];
     }
@@ -165,6 +212,59 @@ protected function getHeaderValue()
         return $value;
     }
 
+    /**
+     * @return string public path to log-file
+     */
+    protected function createLogFile(): string
+    {
+        $this->collectGarbage();
+
+        $content = json_encode(
+            $this->createData($this->entries),
+            JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE
+        );
+
+        $filename = $this->createUniqueFilename();
+
+        $local_path = "{$this->local_path}/{$filename}";
+
+        if (@file_put_contents($local_path, $content) === false) {
+            throw new RuntimeException("unable to write log-file: {$local_path}");
+        }
+
+        return "{$this->public_path}/{$filename}";
+    }
+
+    /**
+     * @return string pseudo-random log filename
+     */
+    protected function createUniqueFilename(): string
+    {
+        return uniqid("log-", true) . ".json";
+    }
+
+    /**
+     * Garbage-collects log-files older than one minute.
+     */
+    protected function collectGarbage()
+    {
+        foreach (glob("{$this->local_path}/*.json") as $path) {
+            $age = $this->getTime() - filemtime($path);
+
+            if ($age > 60) {
+                @unlink($path);
+            }
+        }
+    }
+
+    /**
+     * @return int
+     */
+    protected function getTime(): int
+    {
+        return time();
+    }
+
     /**
      * Encodes the ChromeLogger-compatible data-structure in JSON/base64-format
      *

tests/unit/ChromeLoggerCest.php

@@ -2,12 +2,16 @@
 
 namespace Kodus\Logging\Test\Unit;
 
+use Codeception\Util\FileSystem;
+use function json_decode;
 use Kodus\Logging\ChromeLogger;
 use Mockery;
 use Mockery\MockInterface;
 use Psr\Http\Message\ResponseInterface;
 use RuntimeException;
+use function str_repeat;
 use UnitTester;
+use Zend\Diactoros\Response;
 
 class Foo
 {
@@ -191,6 +195,89 @@ public function truncateExcessiveLogData(UnitTester $I)
         $I->assertEquals(ChromeLogger::LIMIT_WARNING, end($data["rows"])[0][0]);
     }
 
+    public function persistToLocalFiles(UnitTester $I)
+    {
+        $logger = new class extends ChromeLogger
+        {
+            private $time;
+
+            public function __construct()
+            {
+                // NOTE: no call to parent::_construct() here because PHP demands horrible code.
+
+                $this->time = time();
+            }
+
+            public function skipTime(int $time)
+            {
+                $this->time += $time;
+            }
+
+            protected function getTime(): int
+            {
+                return $this->time;
+            }
+        };
+
+        $local_path = dirname(__DIR__) . "/_output/log";
+
+        FileSystem::deleteDir($local_path);
+
+        mkdir($local_path);
+
+        $public_path = "/log";
+
+        $logger->setLimit(2048); // will be ignored!
+
+        $logger->usePersistence($local_path, $public_path);
+
+        $unique_locations = [];
+
+        $generate_log = function () use ($I, $logger, $local_path, &$unique_locations) {
+            // write 20*20*10 = 4000 bytes (over the 2048 limit, which should be ignored)
+
+            $num_rows = 20;
+
+            for ($i=1; $i<= $num_rows; $i++) {
+                $logger->debug(str_repeat("0123456789", 20));
+            }
+
+            $response = new Response(fopen("php://temp", "rw+"));
+
+            $response = $logger->writeToResponse($response);
+
+            $location = $response->getHeaderLine("X-ServerLog-Location");
+
+            $unique_locations[$location] = true;
+
+            $I->assertRegExp('/^\/log\/log-.*\.json$/', $location);
+
+            $contents = file_get_contents("{$local_path}/" . basename($location));
+
+            $I->assertCount($num_rows, json_decode($contents, true)["rows"],
+                "all rows should be written to file, despite being over the header size limit");
+        };
+
+        $num_files = 2;
+
+        for ($i=1; $i<= $num_files; $i++) {
+            $generate_log();
+        }
+
+        $I->assertCount($num_files, $unique_locations,
+            "every generated log should have a unique file-name");
+
+        $I->assertCount($num_files, glob("{$local_path}/*.json"),
+            "no files should have been garbage-collected at this point");
+
+        $logger->skipTime(60 + 1); // log-files expire after 60 seconds
+
+        $generate_log();
+
+        $I->assertCount(1, glob("{$local_path}/*.json"),
+            "previous {$num_files} log-files should be garbage-collected");
+    }
+    
     /**
      * Extract data from the data-header created by a ChromeLogger instance.
      *