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 <tcit@tcit.fr>

diff --git a/lib/private/Log.php b/lib/private/Log.php
index edbfdea7b9deca332ea19173763b615441f67e15..5a6e4c6df44e66dfd5b5966ba75b2664845f45bb 100644 (file)
--- a/lib/private/Log.php
+++ b/lib/private/Log.php
@@ -15,6 +15,7 @@ declare(strict_types=1);
  * @author Olivier Paroz <github@oparoz.com>
  * @author Robin Appelman <robin@icewind.nl>
  * @author Roeland Jago Douma <roeland@famdouma.nl>
+ * @author Thomas Citharel <nextcloud@tcit.fr>
  * @author Thomas Müller <thomas.mueller@tmit.eu>
  * @author Victor Dubiniuk <dubiniuk@owncloud.com>
  *
@@ -207,11 +208,11 @@ class Log implements ILogger, IDataLogger {
                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 @@ class Log implements ILogger, IDataLogger {
                                                        '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 @@ class Log implements ILogger, IDataLogger {
                $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 @@ class Log implements ILogger, IDataLogger {
        /**
         * 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 87ce0396594f97fa8a7afde13d50c2b34b3dd67a..1bb72856240e37e2456730c144541d66f7a0203c 100644 (file)
--- a/lib/private/Log/LogDetails.php
+++ b/lib/private/Log/LogDetails.php
@@ -5,6 +5,7 @@
  * @author Arthur Schiwon <blizzz@arthur-schiwon.de>
  * @author Christoph Wurst <christoph@winzerhof-wurst.at>
  * @author Julius Härtl <jus@bitgrid.net>
+ * @author Thomas Citharel <nextcloud@tcit.fr>
  *
  * @license GNU AGPL version 3 or any later version
  *
@@ -90,8 +91,9 @@ abstract class LogDetails {
                                $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 937b3c754485c801c56923561d6fb8153a567a3d..703c4280f24408c01103434ec010fe179198b132 100644 (file)
--- a/tests/lib/Log/FileTest.php
+++ b/tests/lib/Log/FileTest.php
@@ -1,5 +1,7 @@
 <?php
 /**
+ *
+ * @author Thomas Citharel <nextcloud@tcit.fr>
  *
  * 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 @@ class FileTest extends TestCase {
                $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 @@ class FileTest extends TestCase {
                $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 @@ class FileTest extends TestCase {
                $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 9b44fe198e233515d04a33afc1c46c7d4153bd12..e606f0098dc7e7a6150983ee9cfc01314a50b664 100644 (file)
--- a/tests/lib/LoggerTest.php
+++ b/tests/lib/LoggerTest.php
@@ -1,6 +1,9 @@
 <?php
 /**
  * Copyright (c) 2014 Thomas Müller <thomas.mueller@tmit.eu>
+ *
+ * @author Thomas Citharel <nextcloud@tcit.fr>
+ *
  * 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 @@ class LoggerTest extends TestCase implements IWriter {
                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 @@ class LoggerTest extends TestCase implements IWriter {
                $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 {