Repository: Seldaek/monolog (php)

Issue:
GoogleCloudLoggingFormatter timestamp does not work with Google Cloud Run
Monolog version 2 and 3.

In our application we have a fingers crossed handler that passes to a stream handler that writes to `php://stderr` using the Google Cloud Logging Formatter. This mostly works fine, except that Google Cloud Run does not use the `timestamp` sent from monolog as the timestamp of the message. It seems to be taking the time it received the message instead. 
Most notably when we logged several messages, sleeping for 1 second between those messages, they all more or less the same timestamp in Google Cloud Logging, they certainly weren't a second apart. 

Diving into it, it turns out sending messages through `php://stderr` is different than sending them through the logging API. Instead of `timestamp` the field `time` must be used, and the time must be in UTC.

We found that the following works for us when writing to `php://stderr` on Google Cloud Run (in Monolog 2):

```
$record['time'] = $record['datetime']->setTimezone(new DateTimeZone('UTC'))->format('Y-m-d\TH:i:s.u\Z');
```

With this in place the messages were logged seconds apart, even though they were still logged all at once by the fingers crossed handler.

I do wonder whether this should be changed in Monolog, because I don't know if the current implementation has a use case that I'm unaware off that uses the format that is now in the code (something else than Cloud Run and/or writing to `php://stderr`). 

@lcobucci since you wrote the formatter in Monolog, do you have ideas on this?

Pull request:
Fix date/time field for GCP logging
Fixes #1754

This uses the field that actually maps to the expected format.

More info: https://cloud.google.com/logging/docs/structured-logging

Patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index fa0acea3..0ab01418 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -1,3 +1,7 @@
+### 3.3.0 (unreleased)
+
+  * Added `ClosureContextProcessor` to allow delaying the creation of context data by setting a Closure in context which is called when the log record is used (#1745)
+ 
 ### 3.2.0 (2022-07-24)
 
   * Deprecated `CubeHandler` and `PHPConsoleHandler` as both projects are abandoned and those should not be used anymore (#1734)
diff --git a/doc/02-handlers-formatters-processors.md b/doc/02-handlers-formatters-processors.md
index 96cef403..615731bc 100644
--- a/doc/02-handlers-formatters-processors.md
+++ b/doc/02-handlers-formatters-processors.md
@@ -160,6 +160,7 @@
 ## Processors
 
 - [_PsrLogMessageProcessor_](https://github.com/Seldaek/monolog/blob/main/src/Monolog/Processor/PsrLogMessageProcessor.php): Processes a log record's message according to PSR-3 rules, replacing `{foo}` with the value from `$context['foo']`.
+- [_ClosureContextProcessor_](https://github.com/Seldaek/monolog/blob/main/src/Monolog/Processor/ClosureContextProcessor.php): Allows delaying the creation of context data by setting a Closure in context which is called when the log record is used
 - [_IntrospectionProcessor_](https://github.com/Seldaek/monolog/blob/main/src/Monolog/Processor/IntrospectionProcessor.php): Adds the line/file/class/method from which the log call originated.
 - [_WebProcessor_](https://github.com/Seldaek/monolog/blob/main/src/Monolog/Processor/WebProcessor.php): Adds the current request URI, request method and client IP to a log record.
 - [_MemoryUsageProcessor_](https://github.com/Seldaek/monolog/blob/main/src/Monolog/Processor/MemoryUsageProcessor.php): Adds the current memory usage to a log record.
diff --git a/src/Monolog/Formatter/GoogleCloudLoggingFormatter.php b/src/Monolog/Formatter/GoogleCloudLoggingFormatter.php
index d37d1e0c..ea555d4d 100644
--- a/src/Monolog/Formatter/GoogleCloudLoggingFormatter.php
+++ b/src/Monolog/Formatter/GoogleCloudLoggingFormatter.php
@@ -17,6 +17,7 @@ use Monolog\LogRecord;
 /**
  * Encodes message information into JSON in a format compatible with Cloud logging.
  *
+ * @see https://cloud.google.com/logging/docs/structured-logging
  * @see https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry
  *
  * @author Luís Cobucci <lcobucci@gmail.com>
@@ -29,7 +30,7 @@ final class GoogleCloudLoggingFormatter extends JsonFormatter
 
         // Re-key level for GCP logging
         $normalized['severity'] = $normalized['level_name'];
-        $normalized['timestamp'] = $record->datetime->format(DateTimeInterface::RFC3339_EXTENDED);
+        $normalized['time'] = $record->datetime->format(DateTimeInterface::RFC3339_EXTENDED);
 
         // Remove keys that are not used by GCP
         unset($normalized['level'], $normalized['level_name'], $normalized['datetime']);
diff --git a/src/Monolog/Processor/ClosureContextProcessor.php b/src/Monolog/Processor/ClosureContextProcessor.php
new file mode 100644
index 00000000..514b3547
--- /dev/null
+++ b/src/Monolog/Processor/ClosureContextProcessor.php
@@ -0,0 +1,51 @@
+<?php declare(strict_types=1);
+
+/*
+ * This file is part of the Monolog package.
+ *
+ * (c) Jordi Boggiano <j.boggiano@seld.be>
+ *
+ * For the full copyright and license information, please view the LICENSE
+ * file that was distributed with this source code.
+ */
+
+namespace Monolog\Processor;
+
+use Monolog\LogRecord;
+
+/**
+ * Generates a context from a Closure if the Closure is the only value
+ * in the context
+ *
+ * It helps reduce the performance impact of debug logs if they do
+ * need to create lots of context information. If this processor is added
+ * on the correct handler the context data will only be generated
+ * when the logs are actually logged to that handler, which is useful when
+ * using FingersCrossedHandler or other filtering handlers to conditionally
+ * log records.
+ */
+class ClosureContextProcessor implements ProcessorInterface
+{
+    public function __invoke(LogRecord $record): LogRecord
+    {
+        $context = $record->context;
+        if (isset($context[0]) && 1 === \count($context) && $context[0] instanceof \Closure) {
+            try {
+                $context = $context[0]();
+            } catch (\Throwable $e) {
+                $context = [
+                    'error_on_context_generation' => $e->getMessage(),
+                    'exception' => $e,
+                ];
+            }
+
+            if (!\is_array($context)) {
+                $context = [$context];
+            }
+
+            $record = $record->with(context: $context);
+        }
+
+        return $record;
+    }
+}


Test patch:
diff --git a/tests/Monolog/Formatter/GoogleCloudLoggingFormatterTest.php b/tests/Monolog/Formatter/GoogleCloudLoggingFormatterTest.php
index e46846ae..7888caa7 100644
--- a/tests/Monolog/Formatter/GoogleCloudLoggingFormatterTest.php
+++ b/tests/Monolog/Formatter/GoogleCloudLoggingFormatterTest.php
@@ -30,8 +30,8 @@ class GoogleCloudLoggingFormatterTest extends TestCase
 
         $formatted_decoded = json_decode($formatter->format($record), true);
         $this->assertArrayNotHasKey("datetime", $formatted_decoded);
-        $this->assertArrayHasKey("timestamp", $formatted_decoded);
-        $this->assertSame($record->datetime->format(DateTimeInterface::RFC3339_EXTENDED), $formatted_decoded["timestamp"]);
+        $this->assertArrayHasKey("time", $formatted_decoded);
+        $this->assertSame($record->datetime->format(DateTimeInterface::RFC3339_EXTENDED), $formatted_decoded["time"]);
     }
 
     /**
diff --git a/tests/Monolog/Processor/ClosureContextProcessorTest.php b/tests/Monolog/Processor/ClosureContextProcessorTest.php
new file mode 100644
index 00000000..68a9e729
--- /dev/null
+++ b/tests/Monolog/Processor/ClosureContextProcessorTest.php
@@ -0,0 +1,69 @@
+<?php declare(strict_types=1);
+
+/*
+ * This file is part of the Monolog package.
+ *
+ * (c) Jordi Boggiano <j.boggiano@seld.be>
+ *
+ * For the full copyright and license information, please view the LICENSE
+ * file that was distributed with this source code.
+ */
+
+namespace Monolog\Processor;
+
+use Monolog\Test\TestCase;
+
+class ClosureContextProcessorTest extends TestCase
+{
+    public function testReplace()
+    {
+        $context = ['obj' => new \stdClass()];
+        $processor = new ClosureContextProcessor();
+
+        $record = $processor($this->getRecord(context: [fn () => $context]));
+        $this->assertSame($context, $record->context);
+    }
+
+    /**
+     * @dataProvider getContexts
+     */
+    public function testSkip(array $context)
+    {
+        $processor = new ClosureContextProcessor();
+
+        $record = $processor($this->getRecord(context: $context));
+        $this->assertSame($context, $record->context);
+    }
+
+    public function testClosureReturnsNotArray()
+    {
+        $object = new \stdClass();
+        $processor = new ClosureContextProcessor();
+
+        $record = $processor($this->getRecord(context: [fn () => $object]));
+        $this->assertSame([$object], $record->context);
+    }
+
+    public function testClosureThrows()
+    {
+        $exception = new \Exception('For test.');
+        $expected = [
+            'error_on_context_generation' => 'For test.',
+            'exception' => $exception,
+        ];
+        $processor = new ClosureContextProcessor();
+
+        $record = $processor($this->getRecord(context: [fn () => throw $exception]));
+        $this->assertSame($expected, $record->context);
+    }
+
+    public function getContexts(): iterable
+    {
+        yield [['foo']];
+        yield [['foo' => 'bar']];
+        yield [['foo', 'bar']];
+        yield [['foo', fn () => 'bar']];
+        yield [[fn () => 'foo', 'bar']];
+        yield [['foo' => fn () => 'bar']];
+    }
+}