diff --git a/lib/private/Log.php b/lib/private/Log.php index edbfdea7b9dec..5a6e4c6df44e6 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) { @@ -309,8 +310,11 @@ public function logException(\Throwable $exception, array $context = []) { $level = $context['level'] ?? ILogger::ERROR; $serializer = new ExceptionSerializer($this->config); - $data = $serializer->serializeException($exception); - $data['CustomMessage'] = $this->interpolateMessage($context, $context['message'] ?? '--'); + $data = $context; + unset($data['app']); + unset($data['level']); + $data = array_merge($serializer->serializeException($exception), $data); + $data = $this->interpolateMessage($data, $context['message'] ?? '--', 'CustomMessage'); $minLevel = $this->getLogLevel($context); @@ -375,16 +379,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..e606f0098dc7e 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,18 +12,21 @@ 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 */ @@ -30,8 +36,8 @@ 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 {