Merge pull request #32985 from nextcloud/backport/32242/stable23

[stable23] Fix logging data context to file

4 files changed, 75 insertions, 24 deletions

diff --git a/lib/private/Log.php b/lib/private/Log.php
index edbfdea7b9d..5a6e4c6df44 100644
--- 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 87ce0396594..1bb72856240 100644
--- 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 937b3c75448..703c4280f24 100644
--- a/tests/lib/Log/FileTest.php
+++ b/tests/lib/Log/FileTest.php
@@ -1,6 +1,8 @@
 <?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
  * License as published by the Free Software Foundation; either
@@ -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 9b44fe198e2..e606f0098dc 100644
--- 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 {