Log exceptions as nested array instead of encoded json

Signed-off-by: Robin Appelman <robin@icewind.nl>

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) {
+			call_user_func([$this->logger, 'write'], $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,26 +362,35 @@ 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) {
+				call_user_func([$this->logger, 'write'], $app, $data, $level);
+			} else {
+				$entry = json_encode($data, JSON_PARTIAL_OUTPUT_ON_ERROR);
+				call_user_func([$this->logger, 'write'], $app, $entry, $level);
+			}
+		}
+
 		$context['level'] = $level;
 		if (!is_null($this->crashReporters)) {
 			$this->crashReporters->delegateReport($exception, $context);

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);
 		}
 	}