diff --git a/apps/dav/tests/unit/Connector/Sabre/ExceptionLoggerPluginTest.php b/apps/dav/tests/unit/Connector/Sabre/ExceptionLoggerPluginTest.php index ff928ccede..c1d48a7ce5 100644 --- a/apps/dav/tests/unit/Connector/Sabre/ExceptionLoggerPluginTest.php +++ b/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) { - //disable original constructor - } - - public function log(int $level, string $message, array $context = array()) { + public function writeLog(string $app, $entry, int $level) { $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() { diff --git a/lib/private/Log.php b/lib/private/Log.php index e47f68807d..2c2b7ccb08 100644 --- a/lib/private/Log.php +++ b/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); - $logCondition = $this->config->getValue('log.condition', []); + $minLevel = $this->getLogLevel($context); array_walk($context, [$this->normalizer, 'format']); - if (isset($context['app'])) { - $app = $context['app']; + $app = $context['app'] ?? 'no app in context'; - /** - * 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) { - $minLevel = Util::DEBUG; + if ($this->logConditionSatisfied) { + return Util::DEBUG; } - if ($level >= $minLevel) { - $logger = $this->logger; - call_user_func([$logger, 'write'], $app, $message, $level); + if (isset($context['app'])) { + $logCondition = $this->config->getValue('log.condition', []); + $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; - if (isset($context['level'])) { - $level = $context['level']; - unset($context['level']); - } + $app = $context['app'] ?? 'no app in context'; + $level = $context['level'] ?? Util::ERROR; + $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); - $this->log($level, $msg, $context); + + $minLevel = $this->getLogLevel($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 diff --git a/lib/private/Log/File.php b/lib/private/Log/File.php index ba5027251d..2d7e4b6c14 100644 --- a/lib/private/Log/File.php +++ b/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) { diff --git a/tests/lib/LoggerTest.php b/tests/lib/LoggerTest.php index 6f528bd6fa..9fdbccc24d 100644 --- a/tests/lib/LoggerTest.php +++ b/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); } }