diff --git a/framework/CHANGELOG.md b/framework/CHANGELOG.md index c0f12c9a14..47bb8835e9 100644 --- a/framework/CHANGELOG.md +++ b/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 diff --git a/framework/log/Logger.php b/framework/log/Logger.php index 5081164859..ebd0d756cb 100644 --- a/framework/log/Logger.php +++ b/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; } diff --git a/tests/framework/log/LoggerTest.php b/tests/framework/log/LoggerTest.php index c23da90f67..e4951ac26b 100644 --- a/tests/framework/log/LoggerTest.php +++ b/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); + } } diff --git a/tests/framework/log/TargetTest.php b/tests/framework/log/TargetTest.php index 22db667f0a..2f1d5157b9 100644 --- a/tests/framework/log/TargetTest.php +++ b/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