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>

2 files changed, 52 insertions, 11 deletions

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..bec2119a8ad 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,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 @@ 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 {