fix: Use sub-second timestamps in logs (#2018)

Author: martinstuecklschwaiger

src/Monolog/BreadcrumbHandler.php

@@ -54,13 +54,18 @@ public function __construct(HubInterface $hub, $level = Logger::DEBUG, bool $bub
      */
     protected function write($record): void
     {
+        $datetime = $record['datetime'] ?? null;
+        $timestamp = $datetime instanceof \DateTimeInterface
+            ? $datetime->getTimestamp() + (int) $datetime->format('u') / 1000000
+            : null;
+
         $breadcrumb = new Breadcrumb(
             $this->getBreadcrumbLevel($record['level']),
             $this->getBreadcrumbType($record['level']),
             $record['channel'],
             $record['message'],
             ($record['context'] ?? []) + ($record['extra'] ?? []),
-            $record['datetime']->getTimestamp()
+            $timestamp
         );
 
         $this->hub->addBreadcrumb($breadcrumb);

tests/Monolog/BreadcrumbHandlerTest.php

@@ -15,17 +15,19 @@ final class BreadcrumbHandlerTest extends TestCase
 {
     /**
      * @dataProvider handleDataProvider
+     *
+     * @param LogRecord|array<string, mixed> $record
      */
     public function testHandle($record, Breadcrumb $expectedBreadcrumb): void
     {
         $hub = $this->createMock(HubInterface::class);
         $hub->expects($this->once())
             ->method('addBreadcrumb')
-            ->with($this->callback(function (Breadcrumb $breadcrumb) use ($expectedBreadcrumb, $record): bool {
+            ->with($this->callback(function (Breadcrumb $breadcrumb) use ($expectedBreadcrumb): bool {
                 $this->assertSame($expectedBreadcrumb->getMessage(), $breadcrumb->getMessage());
                 $this->assertSame($expectedBreadcrumb->getLevel(), $breadcrumb->getLevel());
                 $this->assertSame($expectedBreadcrumb->getType(), $breadcrumb->getType());
-                $this->assertEquals($record['datetime']->getTimestamp(), $breadcrumb->getTimestamp());
+                $this->assertEquals($expectedBreadcrumb->getTimestamp(), $breadcrumb->getTimestamp());
                 $this->assertSame($expectedBreadcrumb->getCategory(), $breadcrumb->getCategory());
                 $this->assertEquals($expectedBreadcrumb->getMetadata(), $breadcrumb->getMetadata());
 
@@ -37,16 +39,19 @@ public function testHandle($record, Breadcrumb $expectedBreadcrumb): void
     }
 
     /**
-     * @return iterable<LogRecord|array{array<string, mixed>, Breadcrumb}>
+     * @return iterable<array{LogRecord|array<string, mixed>, Breadcrumb}>
      */
     public static function handleDataProvider(): iterable
     {
+        $now = new \DateTimeImmutable();
+
         $defaultBreadcrumb = new Breadcrumb(
             Breadcrumb::LEVEL_DEBUG,
             Breadcrumb::TYPE_DEFAULT,
             'channel.foo',
             'foo bar',
-            []
+            [],
+            (float) $now->format('U.u')
         );
 
         $levelsToBeTested = [
@@ -58,31 +63,46 @@ public static function handleDataProvider(): iterable
 
         foreach ($levelsToBeTested as $loggerLevel => $breadcrumbLevel) {
             yield 'with level ' . Logger::getLevelName($loggerLevel) => [
-                RecordFactory::create('foo bar', $loggerLevel, 'channel.foo', [], []),
+                RecordFactory::create('foo bar', $loggerLevel, 'channel.foo', [], [], $now),
                 $defaultBreadcrumb->withLevel($breadcrumbLevel),
             ];
         }
 
         yield 'with level ERROR' => [
-            RecordFactory::create('foo bar', Logger::ERROR, 'channel.foo', [], []),
+            RecordFactory::create('foo bar', Logger::ERROR, 'channel.foo', [], [], $now),
             $defaultBreadcrumb->withLevel(Breadcrumb::LEVEL_ERROR)
                 ->withType(Breadcrumb::TYPE_ERROR),
         ];
 
         yield 'with level ALERT' => [
-            RecordFactory::create('foo bar', Logger::ALERT, 'channel.foo', [], []),
+            RecordFactory::create('foo bar', Logger::ALERT, 'channel.foo', [], [], $now),
             $defaultBreadcrumb->withLevel(Breadcrumb::LEVEL_FATAL)
                 ->withType(Breadcrumb::TYPE_ERROR),
         ];
 
         yield 'with context' => [
-            RecordFactory::create('foo bar', Logger::DEBUG, 'channel.foo', ['context' => ['foo' => 'bar']], []),
+            RecordFactory::create('foo bar', Logger::DEBUG, 'channel.foo', ['context' => ['foo' => 'bar']], [], $now),
             $defaultBreadcrumb->withMetadata('context', ['foo' => 'bar']),
         ];
 
         yield 'with extra' => [
-            RecordFactory::create('foo bar', Logger::DEBUG, 'channel.foo', [], ['extra' => ['foo' => 'bar']]),
+            RecordFactory::create('foo bar', Logger::DEBUG, 'channel.foo', [], ['extra' => ['foo' => 'bar']], $now),
             $defaultBreadcrumb->withMetadata('extra', ['foo' => 'bar']),
         ];
+
+        yield 'with timestamp' => [
+            RecordFactory::create('foo bar', Logger::DEBUG, 'channel.foo', [], [], new \DateTimeImmutable('1970-01-01 00:00:42.1337 UTC')),
+            $defaultBreadcrumb->withTimestamp(42.1337),
+        ];
+
+        yield 'with zero timestamp' => [
+            RecordFactory::create('foo bar', Logger::DEBUG, 'channel.foo', [], [], new \DateTimeImmutable('1970-01-01 00:00:00.000 UTC')),
+            $defaultBreadcrumb->withTimestamp(0.0),
+        ];
+
+        yield 'with negative timestamp' => [
+            RecordFactory::create('foo bar', Logger::DEBUG, 'channel.foo', [], [], new \DateTimeImmutable('1969-12-31 23:59:56.859 UTC')),
+            $defaultBreadcrumb->withTimestamp(-3.141),
+        ];
     }
 }

tests/Monolog/RecordFactory.php

@@ -19,11 +19,15 @@ final class RecordFactory
      *
      * @return array<string, mixed>|LogRecord
      */
-    public static function create(string $message, int $level, string $channel, array $context = [], array $extra = [])
+    public static function create(string $message, int $level, string $channel, array $context = [], array $extra = [], ?\DateTimeImmutable $datetime = null)
     {
+        if ($datetime === null) {
+            $datetime = new \DateTimeImmutable();
+        }
+
         if (Logger::API >= 3) {
             return new LogRecord(
-                new \DateTimeImmutable(),
+                $datetime,
                 $channel,
                 Logger::toMonologLevel($level),
                 $message,
@@ -39,7 +43,7 @@ public static function create(string $message, int $level, string $channel, arra
             'level_name' => Logger::getLevelName($level),
             'channel' => $channel,
             'extra' => $extra,
-            'datetime' => new \DateTimeImmutable(),
+            'datetime' => $datetime,
         ];
     }
 }