Skip to content

Commit

Permalink
Log exceptions as nested array instead of encoded json
Browse files Browse the repository at this point in the history 
Signed-off-by: Robin Appelman <[email protected]>
  • Loading branch information
@icewind1991
icewind1991 committed Apr 10, 2018
1 parent 123d9f0 commit b9583c6
Show file tree
Hide file tree
Showing 3 changed files with 104 additions and 50 deletions.
127 changes: 83 additions & 44 deletions lib/private/Log.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,7 @@

use InterfaSys\LogNormalizer\Normalizer;

use OC\Log\File;
use OCP\ILogger;
use OCP\Support\CrashReport\IRegistry;
use OCP\Util;
Expand All @@ -50,7 +51,6 @@
*
* MonoLog is an example implementing this interface.
*/

class Log implements ILogger {

/** @var string */
Expand Down Expand Up @@ -78,7 +78,7 @@ class Log implements ILogger {
'updatePrivateKeyPassword',
'validateUserPass',
'loginWithToken',
'\{closure\}',
'{closure}',

// TokenProvider
'getToken',
Expand Down Expand Up @@ -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']);
Expand Down Expand Up @@ -251,76 +251,106 @@ public function debug(string $message, array $context = []) {
* @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'];

/**
* 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;
}
$app = $context['app'] ?? 'no app in context';

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

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

/**
Expand All @@ -332,26 +362,35 @@ public function log(int $level, string $message, array $context = []) {
* @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) {
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);
Expand Down
2 changes: 1 addition & 1 deletion lib/private/Log/File.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -72,7 +72,7 @@ public static function init() {
/**
* 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) {
Expand Down
25 changes: 20 additions & 5 deletions tests/lib/LoggerTest.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -96,9 +96,12 @@ public function testDetectlogin($user, $password) {

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

Expand All @@ -115,9 +118,12 @@ public function testDetectcheckPassword($user, $password) {

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

Expand All @@ -134,9 +140,12 @@ public function testDetectvalidateUserPass($user, $password) {

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

Expand All @@ -153,9 +162,12 @@ public function testDetecttryLogin($user, $password) {

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

Expand All @@ -177,13 +189,16 @@ public function testDetectclosure($user, $password) {

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

Expand Down

0 comments on commit b9583c6

Please sign in to comment.