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) Only tested with file write logger, but shouldn't work differently. Crash reporters always had the context. Signed-off-by: Thomas Citharel <[email protected]>
nextcloud · May 2, 2022 · 613f608 · 613f608
1 parent 3197ae8
commit 613f608
Show file tree

Hide file tree

Showing 4 changed files with 52 additions and 13 deletions.
diff --git a/lib/private/Log.php b/lib/private/Log.php
@@ -15,6 +15,7 @@
  * @author Olivier Paroz <[email protected]>
  * @author Robin Appelman <[email protected]>
  * @author Roeland Jago Douma <[email protected]>
+ * @author Thomas Citharel <[email protected]>
  * @author Thomas Müller <[email protected]>
  * @author Victor Dubiniuk <[email protected]>
  *
@@ -211,7 +212,9 @@ public function log(int $level, string $message, array $context = []) {
 
 		try {
 			if ($level >= $minLevel) {
-				$this->writeLog($app, $message, $level);
+				$contextWithMessage = $context;
+				$contextWithMessage['message'] = $message;
+				$this->writeLog($app, $contextWithMessage, $level);
 
 				if ($this->crashReporters !== null) {
 					$messageContext = array_merge(

diff --git a/lib/private/Log/LogDetails.php b/lib/private/Log/LogDetails.php
@@ -5,6 +5,7 @@
  * @author Arthur Schiwon <[email protected]>
  * @author Christoph Wurst <[email protected]>
  * @author Julius Härtl <[email protected]>
+ * @author Thomas Citharel <[email protected]>
  *
  * @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
@@ -1,5 +1,7 @@
 <?php
 /**
+ *
+ * @author Thomas Citharel <[email protected]>
  *
  * 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
@@ -9,29 +9,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 +66,19 @@ public function testAppCondition() {
 		$this->assertEquals($expected, $this->getLogs());
 	}
 
-	private function getLogs() {
+	public function testLogging(): 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']);
+		$logFile->error('Testing logging', ['something' => 'extra']);
+	}
+
+	private function getLogs(): array {
 		return $this->logs;
 	}
 
 	public function write(string $app, $message, int $level) {
-		$this->logs[] = "$level $message";
+		$this->logs[] = $level . " " . $message['message'];
 	}
 
 	public function userAndPasswordData(): array {