Fix #18274: Fix `yii\log\Logger` to calculate profile timings no matter the value of the flush interval

framework/CHANGELOG.md

@@ -20,6 +20,7 @@ Yii Framework 2 Change Log
 - Enh #18726: Added `yii\helpers\Json::$prettyPrint` (rhertogh)
 - Enh #18734: Added `yii\validators\EmailValidator::$enableLocalIDN` (brandonkelly)
 - Enh #18656: Added ability for `yii serve`'s `--router` param to take an alias (markhuot)
+- Bug #18274: Fix `yii\log\Logger` to calculate profile timings no matter the value of the flush interval (bizley)
 
 
 2.0.42.1 May 06, 2021

framework/log/Logger.php

@@ -108,7 +108,7 @@ class Logger extends Component
      */
     public $traceLevel = 0;
     /**
-     * @var Dispatcher the message dispatcher
+     * @var Dispatcher the message dispatcher.
      */
     public $dispatcher;
     /**
@@ -117,6 +117,13 @@ class Logger extends Component
      */
     public $dbEventNames = ['yii\db\Command::query', 'yii\db\Command::execute'];
 
+    /**
+     * @var array of profiling related messages.
+     * Structure of a log message is the same as in [[$messages]].
+     * @since 2.0.43
+     */
+    protected $profileMessages = [];
+
 
     /**
      * Initializes the logger by registering [[flush()]] as a shutdown function.
@@ -162,7 +169,11 @@ class Logger extends Component
                 }
             }
         }
-        $this->messages[] = [$message, $level, $category, $time, $traces, memory_get_usage()];
+        $data = [$message, $level, $category, $time, $traces, memory_get_usage()];
+        $this->messages[] = $data;
+        if ($level == self::LEVEL_PROFILE_BEGIN || $level == self::LEVEL_PROFILE_END) {
+            $this->profileMessages[] = $data;
+        }
         if ($this->flushInterval > 0 && count($this->messages) >= $this->flushInterval) {
             $this->flush();
         }
@@ -213,7 +224,7 @@ class Logger extends Component
      */
     public function getProfiling($categories = [], $excludeCategories = [])
     {
-        $timings = $this->calculateTimings($this->messages);
+        $timings = $this->calculateTimings($this->profileMessages);
         if (empty($categories) && empty($excludeCategories)) {
             return $timings;
         }

tests/framework/log/LoggerTest.php

@@ -341,16 +341,15 @@ class LoggerTest extends TestCase
      */
     public function testGetProfilingWithEmptyCategoriesAndExcludeCategories()
     {
-        $messages = ['anyData'];
         $returnValue = 'return value';
         /* @var $logger Logger|\PHPUnit_Framework_MockObject_MockObject */
         $logger = $this->getMockBuilder('yii\log\Logger')
             ->setMethods(['calculateTimings'])
             ->getMock();
 
-        $logger->messages = $messages;
+        $logger->messages = ['anyData'];
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with($this->equalTo($messages));
+        $logger->expects($this->once())->method('calculateTimings')->with([]);
         $this->assertEquals($returnValue, $logger->getProfiling());
     }
 
@@ -377,7 +376,7 @@ class LoggerTest extends TestCase
 
         $logger->messages = $messages;
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with($this->equalTo($messages));
+        $logger->expects($this->once())->method('calculateTimings')->with([]);
         $this->assertEquals([], $logger->getProfiling(['not-matched-category']));
     }
 
@@ -417,7 +416,7 @@ class LoggerTest extends TestCase
 
         $logger->messages = $messages;
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with($this->equalTo($messages));
+        $logger->expects($this->once())->method('calculateTimings')->with([]);
         $this->assertEquals([$matchedByCategoryName], $logger->getProfiling(['category']));
 
         /*
@@ -430,7 +429,7 @@ class LoggerTest extends TestCase
 
         $logger->messages = $messages;
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with($this->equalTo($messages));
+        $logger->expects($this->once())->method('calculateTimings')->with([]);
         $this->assertEquals([$matchedByCategoryName, $secondCategory], $logger->getProfiling(['category*']));
     }
 
@@ -479,7 +478,7 @@ class LoggerTest extends TestCase
 
         $logger->messages = $messages;
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with($this->equalTo($messages));
+        $logger->expects($this->once())->method('calculateTimings')->with([]);
         $this->assertEquals([$fistCategory, $secondCategory], $logger->getProfiling(['cat*'], ['category3']));
 
         /*
@@ -492,7 +491,48 @@ class LoggerTest extends TestCase
 
         $logger->messages = $messages;
         $logger->method('calculateTimings')->willReturn($returnValue);
-        $logger->expects($this->once())->method('calculateTimings')->with($this->equalTo($messages));
+        $logger->expects($this->once())->method('calculateTimings')->with([]);
         $this->assertEquals([$fistCategory], $logger->getProfiling(['cat*'], ['category*']));
     }
+
+    public function providerForNonProfilingMessages()
+    {
+        return [
+            [Logger::LEVEL_ERROR],
+            [Logger::LEVEL_WARNING],
+            [Logger::LEVEL_INFO],
+            [Logger::LEVEL_TRACE],
+            [Logger::LEVEL_PROFILE],
+        ];
+    }
+
+    /**
+     * @dataProvider providerForNonProfilingMessages
+     */
+    public function testGatheringNonProfilingMessages($level)
+    {
+        $logger = new Logger(['flushInterval' => 0]);
+        $logger->log('aaa', $level);
+        $logger->log('aaa', Logger::LEVEL_PROFILE_END);
+        $this->assertSame([], $logger->getProfiling());
+        $this->assertCount(2, $logger->messages);
+    }
+
+    public function testGatheringProfilingMessages()
+    {
+        $logger = new Logger(['flushInterval' => 0]);
+        $logger->log('aaa', Logger::LEVEL_PROFILE_BEGIN);
+        $logger->log('aaa', Logger::LEVEL_PROFILE_END);
+        $this->assertCount(1, $logger->getProfiling());
+        $profiling = $logger->getProfiling()[0];
+        $this->assertSame('aaa', $profiling['info']);
+        $this->assertSame('application', $profiling['category']);
+        $this->assertSame(0, $profiling['level']);
+        $this->assertSame([], $profiling['trace']);
+        $this->assertArrayHasKey('timestamp', $profiling);
+        $this->assertArrayHasKey('duration', $profiling);
+        $this->assertArrayHasKey('memory', $profiling);
+        $this->assertArrayHasKey('memoryDiff', $profiling);
+        $this->assertCount(2, $logger->messages);
+    }
 }

tests/framework/log/TargetTest.php

@@ -236,6 +236,26 @@ class TargetTest extends TestCase
         $this->assertCount(6, static::$messages[0]);
         $this->assertCount(6, static::$messages[1]);
     }
+
+    public function testBreakProfilingWithFlush()
+    {
+        $logger = new Logger();
+        new Dispatcher([
+            'logger' => $logger,
+            'targets' => [new TestTarget()],
+            'flushInterval' => 2,
+        ]);
+
+        $logger->log('token.a', Logger::LEVEL_PROFILE_BEGIN, 'category');
+        $logger->log('info', Logger::LEVEL_INFO, 'category');
+        $logger->log('token.a', Logger::LEVEL_PROFILE_END, 'category');
+
+        $timings = $logger->getProfiling(['category']);
+
+        self::assertCount(1, $timings);
+        self::assertArrayHasKey('info', $timings[0]);
+        self::assertArrayHasKey('category', $timings[0]);
+    }
 }
 
 class TestTarget extends Target