Merge pull request #8946 from nextcloud/log-exceptions-as-nested-array-2

Log exceptions as nested array instead of encoded json

apps/dav/tests/unit/Connector/Sabre/ExceptionLoggerPluginTest.php

@@ -24,6 +24,7 @@
 
 namespace OCA\DAV\Tests\unit\Connector\Sabre;
 
+use OC\SystemConfig;
 use OCA\DAV\Connector\Sabre\Exception\InvalidPath;
 use OCA\DAV\Connector\Sabre\ExceptionLoggerPlugin as PluginToTest;
 use OC\Log;
@@ -37,13 +38,9 @@ class TestLogger extends Log {
 	public $message;
 	public $level;
 
-	public function __construct($logger = null) {
+	public function writeLog(string $app, $entry, int $level) {
-		//disable original constructor
-	}
-
-	public function log(int $level, string $message, array $context = array()) {
 		$this->level = $level;
-		$this->message = $message;
+		$this->message = $entry;
 	}
 }
 
@@ -59,8 +56,20 @@ class ExceptionLoggerPluginTest extends TestCase {
 	private $logger;
 
 	private function init() {
+		$config = $this->createMock(SystemConfig::class);
+		$config->expects($this->any())
+			->method('getValue')
+			->willReturnCallback(function($key, $default) {
+				switch ($key) {
+					case 'loglevel':
+						return 0;
+					default:
+						return $default;
+				}
+			});
+
 		$this->server = new Server();
-		$this->logger = new TestLogger();
+		$this->logger = new TestLogger(Log\File::class, $config);
 		$this->plugin = new PluginToTest('unit-test', $this->logger);
 		$this->plugin->initialize($this->server);
 	}
@@ -73,7 +82,8 @@ class ExceptionLoggerPluginTest extends TestCase {
 		$this->plugin->logException($exception);
 
 		$this->assertEquals($expectedLogLevel, $this->logger->level);
-		$this->assertStringStartsWith('Exception: {"Exception":' . json_encode(get_class($exception)) . ',"Message":"' . $expectedMessage . '",', $this->logger->message);
+		$this->assertEquals(get_class($exception), $this->logger->message['Exception']);
+		$this->assertEquals($expectedMessage, $this->logger->message['Message']);
 	}
 
 	public function providesExceptions() {

lib/private/Log.php

@@ -37,6 +37,7 @@ namespace OC;
 
 use InterfaSys\LogNormalizer\Normalizer;
 
+use OC\Log\File;
 use OCP\ILogger;
 use OCP\Support\CrashReport\IRegistry;
 use OCP\Util;
@@ -50,7 +51,6 @@ use OCP\Util;
  *
  * MonoLog is an example implementing this interface.
  */
-
 class Log implements ILogger {
 
 	/** @var string */
@@ -78,7 +78,7 @@ class Log implements ILogger {
 		'updatePrivateKeyPassword',
 		'validateUserPass',
 		'loginWithToken',
-		'\{closure\}',
+		'{closure}',
 
 		// TokenProvider
 		'getToken',
@@ -120,14 +120,14 @@ class Log implements ILogger {
 	 */
 	public function __construct($logger = null, SystemConfig $config = null, $normalizer = null, IRegistry $registry = null) {
 		// FIXME: Add this for backwards compatibility, should be fixed at some point probably
-		if($config === null) {
+		if ($config === null) {
 			$config = \OC::$server->getSystemConfig();
 		}
 
 		$this->config = $config;
 
 		// FIXME: Add this for backwards compatibility, should be fixed at some point probably
-		if($logger === null) {
+		if ($logger === null) {
 			$logType = $this->config->getValue('log_type', 'file');
 			$this->logger = static::getLogClass($logType);
 			call_user_func([$this->logger, 'init']);
@@ -251,61 +251,50 @@ class Log implements ILogger {
 	 * @return void
 	 */
 	public function log(int $level, string $message, array $context = []) {
-		$minLevel = min($this->config->getValue('loglevel', Util::WARN), Util::FATAL);
+		$minLevel = $this->getLogLevel($context);
-		$logCondition = $this->config->getValue('log.condition', []);
 
 		array_walk($context, [$this->normalizer, 'format']);
 
-		if (isset($context['app'])) {
+		$app = $context['app'] ?? 'no app in context';
-			$app = $context['app'];
 
-			/**
-			 * check log condition based on the context of each log message
-			 * once this is met -> change the required log level to debug
-			 */
-			if(!empty($logCondition)
-				&& isset($logCondition['apps'])
-				&& in_array($app, $logCondition['apps'], true)) {
-				$minLevel = Util::DEBUG;
-			}
-
-		} else {
-			$app = 'no app in context';
-		}
 		// interpolate $message as defined in PSR-3
 		$replace = [];
 		foreach ($context as $key => $val) {
 			$replace['{' . $key . '}'] = $val;
 		}
-
-		// interpolate replacement values into the message and return
 		$message = strtr($message, $replace);
 
+		if ($level >= $minLevel) {
+			$this->writeLog($app, $message, $level);
+		}
+	}
+
+	private function getLogLevel($context) {
 		/**
 		 * check for a special log condition - this enables an increased log on
 		 * a per request/user base
 		 */
-		if($this->logConditionSatisfied === null) {
+		if ($this->logConditionSatisfied === null) {
 			// default to false to just process this once per request
 			$this->logConditionSatisfied = false;
-			if(!empty($logCondition)) {
+			if (!empty($logCondition)) {
 
 				// check for secret token in the request
-				if(isset($logCondition['shared_secret'])) {
+				if (isset($logCondition['shared_secret'])) {
 					$request = \OC::$server->getRequest();
 
 					// if token is found in the request change set the log condition to satisfied
-					if($request && hash_equals($logCondition['shared_secret'], $request->getParam('log_secret', ''))) {
+					if ($request && hash_equals($logCondition['shared_secret'], $request->getParam('log_secret', ''))) {
 						$this->logConditionSatisfied = true;
 					}
 				}
 
 				// check for user
-				if(isset($logCondition['users'])) {
+				if (isset($logCondition['users'])) {
 					$user = \OC::$server->getUserSession()->getUser();
 
 					// if the user matches set the log condition to satisfied
-					if($user !== null && in_array($user->getUID(), $logCondition['users'], true)) {
+					if ($user !== null && in_array($user->getUID(), $logCondition['users'], true)) {
 						$this->logConditionSatisfied = true;
 					}
 				}
@@ -313,14 +302,55 @@ class Log implements ILogger {
 		}
 
 		// if log condition is satisfied change the required log level to DEBUG
-		if($this->logConditionSatisfied) {
+		if ($this->logConditionSatisfied) {
-			$minLevel = Util::DEBUG;
+			return Util::DEBUG;
 		}
 
-		if ($level >= $minLevel) {
+		if (isset($context['app'])) {
-			$logger = $this->logger;
+			$logCondition = $this->config->getValue('log.condition', []);
-			call_user_func([$logger, 'write'], $app, $message, $level);
+			$app = $context['app'];
+
+			/**
+			 * check log condition based on the context of each log message
+			 * once this is met -> change the required log level to debug
+			 */
+			if (!empty($logCondition)
+				&& isset($logCondition['apps'])
+				&& in_array($app, $logCondition['apps'], true)) {
+				return Util::DEBUG;
+			}
 		}
+
+		return min($this->config->getValue('loglevel', Util::WARN), Util::FATAL);
+	}
+
+	private function filterTrace(array $trace) {
+		$sensitiveValues = [];
+		$trace = array_map(function (array $traceLine) use (&$sensitiveValues) {
+			foreach ($this->methodsWithSensitiveParameters as $sensitiveMethod) {
+				if (strpos($traceLine['function'], $sensitiveMethod) !== false) {
+					$sensitiveValues = array_merge($sensitiveValues, $traceLine['args']);
+					$traceLine['args'] = ['*** sensitive parameters replaced ***'];
+					return $traceLine;
+				}
+			}
+			return $traceLine;
+		}, $trace);
+		return array_map(function (array $traceLine) use ($sensitiveValues) {
+			$traceLine['args'] = $this->removeValuesFromArgs($traceLine['args'], $sensitiveValues);
+			return $traceLine;
+		}, $trace);
+	}
+
+	private function removeValuesFromArgs($args, $values) {
+		foreach($args as &$arg) {
+			if (in_array($arg, $values, true)) {
+				$arg = '*** sensitive parameter replaced ***';
+			} else if (is_array($arg)) {
+				$arg = $this->removeValuesFromArgs($arg, $values);
+			}
+		}
+		return $args;
 	}
 
 	/**
@@ -332,32 +362,48 @@ class Log implements ILogger {
 	 * @since 8.2.0
 	 */
 	public function logException(\Throwable $exception, array $context = []) {
-		$level = Util::ERROR;
+		$app = $context['app'] ?? 'no app in context';
-		if (isset($context['level'])) {
+		$level = $context['level'] ?? Util::ERROR;
-			$level = $context['level'];
+
-			unset($context['level']);
-		}
 		$data = [
+			'CustomMessage' => $context['message'] ?? '--',
 			'Exception' => get_class($exception),
 			'Message' => $exception->getMessage(),
 			'Code' => $exception->getCode(),
-			'Trace' => $exception->getTraceAsString(),
+			'Trace' => $this->filterTrace($exception->getTrace()),
 			'File' => $exception->getFile(),
 			'Line' => $exception->getLine(),
 		];
-		$data['Trace'] = preg_replace('!(' . implode('|', $this->methodsWithSensitiveParameters) . ')\(.*\)!', '$1(*** sensitive parameters replaced ***)', $data['Trace']);
 		if ($exception instanceof HintException) {
 			$data['Hint'] = $exception->getHint();
 		}
-		$msg = isset($context['message']) ? $context['message'] : 'Exception';
+
-		$msg .= ': ' . json_encode($data);
+		$minLevel = $this->getLogLevel($context);
-		$this->log($level, $msg, $context);
+
+		array_walk($context, [$this->normalizer, 'format']);
+
+		if ($level >= $minLevel) {
+			if ($this->logger !== File::class) {
+				$data = json_encode($data, JSON_PARTIAL_OUTPUT_ON_ERROR);
+			}
+			$this->writeLog($app, $data, $level);
+		}
+
 		$context['level'] = $level;
 		if (!is_null($this->crashReporters)) {
 			$this->crashReporters->delegateReport($exception, $context);
 		}
 	}
 
+	/**
+	 * @param string $app
+	 * @param string|array $entry
+	 * @param int $level
+	 */
+	protected function writeLog(string $app, $entry, int $level) {
+		call_user_func([$this->logger, 'write'], $app, $entry, $level);
+	}
+
 	/**
 	 * @param string $logType
 	 * @return string

lib/private/Log/File.php

@@ -72,7 +72,7 @@ class File {
 	/**
 	 * write a message in the log
 	 * @param string $app
-	 * @param string $message
+	 * @param string|array $message
 	 * @param int $level
 	 */
 	public static function write($app, $message, $level) {

tests/lib/LoggerTest.php

@@ -96,9 +96,12 @@ class LoggerTest extends TestCase {
 
 		$logLines = $this->getLogs();
 		foreach($logLines as $logLine) {
+			if (is_array($logLine)) {
+				$logLine = json_encode($logLine);
+			}
 			$this->assertNotContains($user, $logLine);
 			$this->assertNotContains($password, $logLine);
-			$this->assertContains('login(*** sensitive parameters replaced ***)', $logLine);
+			$this->assertContains('*** sensitive parameters replaced ***', $logLine);
 		}
 	}
 
@@ -115,9 +118,12 @@ class LoggerTest extends TestCase {
 
 		$logLines = $this->getLogs();
 		foreach($logLines as $logLine) {
+			if (is_array($logLine)) {
+				$logLine = json_encode($logLine);
+			}
 			$this->assertNotContains($user, $logLine);
 			$this->assertNotContains($password, $logLine);
-			$this->assertContains('checkPassword(*** sensitive parameters replaced ***)', $logLine);
+			$this->assertContains('*** sensitive parameters replaced ***', $logLine);
 		}
 	}
 
@@ -134,9 +140,12 @@ class LoggerTest extends TestCase {
 
 		$logLines = $this->getLogs();
 		foreach($logLines as $logLine) {
+			if (is_array($logLine)) {
+				$logLine = json_encode($logLine);
+			}
 			$this->assertNotContains($user, $logLine);
 			$this->assertNotContains($password, $logLine);
-			$this->assertContains('validateUserPass(*** sensitive parameters replaced ***)', $logLine);
+			$this->assertContains('*** sensitive parameters replaced ***', $logLine);
 		}
 	}
 
@@ -153,9 +162,12 @@ class LoggerTest extends TestCase {
 
 		$logLines = $this->getLogs();
 		foreach($logLines as $logLine) {
+			if (is_array($logLine)) {
+				$logLine = json_encode($logLine);
+			}
 			$this->assertNotContains($user, $logLine);
 			$this->assertNotContains($password, $logLine);
-			$this->assertContains('tryLogin(*** sensitive parameters replaced ***)', $logLine);
+			$this->assertContains('*** sensitive parameters replaced ***', $logLine);
 		}
 	}
 
@@ -177,13 +189,16 @@ class LoggerTest extends TestCase {
 
 		$logLines = $this->getLogs();
 		foreach($logLines as $logLine) {
+			if (is_array($logLine)) {
+				$logLine = json_encode($logLine);
+			}
 			$log = explode('\n', $logLine);
 			unset($log[1]); // Remove `testDetectclosure(` because we are not testing this here, but the closure on stack trace 0
 			$logLine = implode('\n', $log);
 
 			$this->assertNotContains($user, $logLine);
 			$this->assertNotContains($password, $logLine);
-			$this->assertContains('{closure}(*** sensitive parameters replaced ***)', $logLine);
+			$this->assertContains('*** sensitive parameters replaced ***', $logLine);
 		}
 	}