From 2a813bab905595bcb2afd9aff6a78645e6b1ce5d Mon Sep 17 00:00:00 2001 From: Thomas Citharel Date: Mon, 2 May 2022 17:49:32 +0200 Subject: [PATCH] Fix logging data context to file It was only logged when an exception was provided or when using logData (which is not being much used). We make sure the interpolated parameters are not logged. Only tested with file write logger, but shouldn't work differently. Crash reporters always had the context. Signed-off-by: Thomas Citharel --- lib/private/Log.php | 27 ++++++++++++++++----------- lib/private/Log/LogDetails.php | 4 +++- tests/lib/Log/FileTest.php | 30 +++++++++++++++++++++++++++--- tests/lib/LoggerTest.php | 33 +++++++++++++++++++++++++-------- 4 files changed, 71 insertions(+), 23 deletions(-) diff --git a/lib/private/Log.php b/lib/private/Log.php index edbfdea7b9dec..4ec88761415f2 100644 --- a/lib/private/Log.php +++ b/lib/private/Log.php @@ -15,6 +15,7 @@ * @author Olivier Paroz * @author Robin Appelman * @author Roeland Jago Douma + * @author Thomas Citharel * @author Thomas Müller * @author Victor Dubiniuk * @@ -207,11 +208,11 @@ public function log(int $level, string $message, array $context = []) { array_walk($context, [$this->normalizer, 'format']); $app = $context['app'] ?? 'no app in context'; - $message = $this->interpolateMessage($context, $message); + $entry = $this->interpolateMessage($context, $message); try { if ($level >= $minLevel) { - $this->writeLog($app, $message, $level); + $this->writeLog($app, $entry, $level); if ($this->crashReporters !== null) { $messageContext = array_merge( @@ -220,11 +221,11 @@ public function log(int $level, string $message, array $context = []) { 'level' => $level ] ); - $this->crashReporters->delegateMessage($message, $messageContext); + $this->crashReporters->delegateMessage($entry['message'], $messageContext); } } else { if ($this->crashReporters !== null) { - $this->crashReporters->delegateBreadcrumb($message, 'log', $context); + $this->crashReporters->delegateBreadcrumb($entry['message'], 'log', $context); } } } catch (\Throwable $e) { @@ -375,16 +376,20 @@ public function getLogPath():string { /** * Interpolate $message as defined in PSR-3 * - * @param array $context - * @param string $message - * - * @return string + * Returns an array containing the context without the interpolated + * parameters placeholders and the message as the 'message' - or + * user-defined - key. */ - private function interpolateMessage(array $context, string $message): string { + private function interpolateMessage(array $context, string $message, string $messageKey = 'message'): array { $replace = []; + $usedContextKeys = []; foreach ($context as $key => $val) { - $replace['{' . $key . '}'] = $val; + $fullKey = '{' . $key . '}'; + $replace[$fullKey] = $val; + if (strpos($message, $fullKey) !== false) { + $usedContextKeys[$key] = true; + } } - return strtr($message, $replace); + return array_merge(array_diff_key($context, $usedContextKeys), [$messageKey => strtr($message, $replace)]); } } diff --git a/lib/private/Log/LogDetails.php b/lib/private/Log/LogDetails.php index 87ce0396594f9..1bb72856240e3 100644 --- a/lib/private/Log/LogDetails.php +++ b/lib/private/Log/LogDetails.php @@ -5,6 +5,7 @@ * @author Arthur Schiwon * @author Christoph Wurst * @author Julius Härtl + * @author Thomas Citharel * * @license GNU AGPL version 3 or any later version * @@ -90,8 +91,9 @@ public function logDetails(string $app, $message, int $level): array { $entry['exception'] = $message; $entry['message'] = $message['CustomMessage'] !== '--' ? $message['CustomMessage'] : $message['Message']; } else { - $entry['data'] = $message; $entry['message'] = $message['message'] ?? '(no message provided)'; + unset($message['message']); + $entry['data'] = $message; } } diff --git a/tests/lib/Log/FileTest.php b/tests/lib/Log/FileTest.php index 937b3c754485c..703c4280f2440 100644 --- a/tests/lib/Log/FileTest.php +++ b/tests/lib/Log/FileTest.php @@ -1,5 +1,7 @@ * * This library is free software; you can redistribute it and/or * modify it under the terms of the GNU AFFERO GENERAL PUBLIC LICENSE @@ -18,6 +20,7 @@ namespace Test\Log; use OC\Log\File; +use OCP\IConfig; use OCP\ILogger; use Test\TestCase; @@ -36,7 +39,7 @@ protected function setUp(): void { $config = \OC::$server->getSystemConfig(); $this->restore_logfile = $config->getValue("logfile"); $this->restore_logdateformat = $config->getValue('logdateformat'); - + $config->setValue("logfile", $config->getValue('datadirectory') . "/logtest.log"); $this->logFile = new File($config->getValue('datadirectory') . '/logtest.log', '', $config); } @@ -55,7 +58,28 @@ protected function tearDown(): void { $this->logFile = new File($this->restore_logfile, '', $config); parent::tearDown(); } - + + public function testLogging() { + $config = \OC::$server->get(IConfig::class); + # delete old logfile + unlink($config->getSystemValue('logfile')); + + # set format & write log line + $config->setSystemValue('logdateformat', 'u'); + $this->logFile->write('code', ['something' => 'extra', 'message' => 'Testing logging'], ILogger::ERROR); + + # read log line + $handle = @fopen($config->getSystemValue('logfile'), 'r'); + $line = fread($handle, 1000); + fclose($handle); + + # check log has data content + $values = (array) json_decode($line, true); + $this->assertArrayNotHasKey('message', $values['data']); + $this->assertEquals('extra', $values['data']['something']); + $this->assertEquals('Testing logging', $values['message']); + } + public function testMicrosecondsLogTimestamp() { $config = \OC::$server->getConfig(); # delete old logfile @@ -69,7 +93,7 @@ public function testMicrosecondsLogTimestamp() { $handle = @fopen($config->getSystemValue('logfile'), 'r'); $line = fread($handle, 1000); fclose($handle); - + # check timestamp has microseconds part $values = (array) json_decode($line); $microseconds = $values['time']; diff --git a/tests/lib/LoggerTest.php b/tests/lib/LoggerTest.php index 9b44fe198e233..bec2119a8ad04 100644 --- a/tests/lib/LoggerTest.php +++ b/tests/lib/LoggerTest.php @@ -1,6 +1,9 @@ + * + * @author Thomas Citharel + * * This file is licensed under the Affero General Public License version 3 or * later. * See the COPYING-README file. @@ -9,29 +12,32 @@ namespace Test; use OC\Log; +use OC\SystemConfig; use OCP\ILogger; use OCP\Log\IWriter; +use OCP\Support\CrashReport\IRegistry; +use PHPUnit\Framework\MockObject\MockObject; class LoggerTest extends TestCase implements IWriter { - /** @var \OC\SystemConfig|\PHPUnit\Framework\MockObject\MockObject */ + /** @var SystemConfig|MockObject */ private $config; - /** @var \OCP\Support\CrashReport\IRegistry|\PHPUnit\Framework\MockObject\MockObject */ + /** @var IRegistry|MockObject */ private $registry; - /** @var \OCP\ILogger */ + /** @var ILogger */ private $logger; /** @var array */ - private $logs = []; + private array $logs = []; protected function setUp(): void { parent::setUp(); $this->logs = []; - $this->config = $this->createMock(\OC\SystemConfig::class); - $this->registry = $this->createMock(\OCP\Support\CrashReport\IRegistry::class); + $this->config = $this->createMock(SystemConfig::class); + $this->registry = $this->createMock(IRegistry::class); $this->logger = new Log($this, $this->config, null, $this->registry); } @@ -63,12 +69,23 @@ public function testAppCondition() { $this->assertEquals($expected, $this->getLogs()); } - private function getLogs() { + public function testLoggingWithDataArray(): void { + $writerMock = $this->createMock(IWriter::class); + $logFile = new Log($writerMock, $this->config); + $writerMock->expects($this->once())->method('write')->with('no app in context', ['something' => 'extra', 'message' => 'Testing logging with john']); + $logFile->error('Testing logging with {user}', ['something' => 'extra', 'user' => 'john']); + } + + private function getLogs(): array { return $this->logs; } public function write(string $app, $message, int $level) { - $this->logs[] = "$level $message"; + $textMessage = $message; + if (is_array($message)) { + $textMessage = $message['message']; + } + $this->logs[] = $level . " " . $textMessage; } public function userAndPasswordData(): array {