Skip to content

Commit 58526d6

Browse files
icewind1991icewind1991
committed
Log exceptions as nested array instead of encoded json
Signed-off-by: Robin Appelman <robin@icewind.nl>
1 parent 123d9f0 commit 58526d6

File tree

3 files changed

+104
-50
lines changed

3 files changed

+104
-50
lines changed

‎lib/private/Log.php‎

Lines changed: 83 additions & 44 deletions
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,7 @@
3737

3838
use InterfaSys\LogNormalizer\Normalizer;
3939

40+
use OC\Log\File;
4041
use OCP\ILogger;
4142
use OCP\Support\CrashReport\IRegistry;
4243
use OCP\Util;
@@ -50,7 +51,6 @@
5051
*
5152
* MonoLog is an example implementing this interface.
5253
*/
53-
5454
class Log implements ILogger {
5555

5656
/** @var string */
@@ -78,7 +78,7 @@ class Log implements ILogger {
7878
'updatePrivateKeyPassword',
7979
'validateUserPass',
8080
'loginWithToken',
81-
'\{closure\}',
81+
'{closure}',
8282

8383
// TokenProvider
8484
'getToken',
@@ -120,14 +120,14 @@ class Log implements ILogger {
120120
*/
121121
public function __construct($logger = null, SystemConfig $config = null, $normalizer = null, IRegistry $registry = null) {
122122
// FIXME: Add this for backwards compatibility, should be fixed at some point probably
123-
if($config === null) {
123+
if ($config === null) {
124124
$config = \OC::$server->getSystemConfig();
125125
}
126126

127127
$this->config = $config;
128128

129129
// FIXME: Add this for backwards compatibility, should be fixed at some point probably
130-
if($logger === null) {
130+
if ($logger === null) {
131131
$logType = $this->config->getValue('log_type', 'file');
132132
$this->logger = static::getLogClass($logType);
133133
call_user_func([$this->logger, 'init']);
@@ -251,76 +251,106 @@ public function debug(string $message, array $context = []) {
251251
* @return void
252252
*/
253253
public function log(int $level, string $message, array $context = []) {
254-
$minLevel = min($this->config->getValue('loglevel', Util::WARN), Util::FATAL);
255-
$logCondition = $this->config->getValue('log.condition', []);
254+
$minLevel = $this->getLogLevel($context);
256255

257256
array_walk($context, [$this->normalizer, 'format']);
258257

259-
if (isset($context['app'])) {
260-
$app = $context['app'];
261-
262-
/**
263-
* check log condition based on the context of each log message
264-
* once this is met -> change the required log level to debug
265-
*/
266-
if(!empty($logCondition)
267-
&& isset($logCondition['apps'])
268-
&& in_array($app, $logCondition['apps'], true)) {
269-
$minLevel = Util::DEBUG;
270-
}
258+
$app = $context['app'] ?? 'no app in context';
271259

272-
} else {
273-
$app = 'no app in context';
274-
}
275260
// interpolate $message as defined in PSR-3
276261
$replace = [];
277262
foreach ($context as $key => $val) {
278263
$replace['{' . $key . '}'] = $val;
279264
}
280-
281-
// interpolate replacement values into the message and return
282265
$message = strtr($message, $replace);
283266

267+
if ($level >= $minLevel) {
268+
call_user_func([$this->logger, 'write'], $app, $message, $level);
269+
}
270+
}
271+
272+
private function getLogLevel($context) {
284273
/**
285274
* check for a special log condition - this enables an increased log on
286275
* a per request/user base
287276
*/
288-
if($this->logConditionSatisfied === null) {
277+
if ($this->logConditionSatisfied === null) {
289278
// default to false to just process this once per request
290279
$this->logConditionSatisfied = false;
291-
if(!empty($logCondition)) {
280+
if (!empty($logCondition)) {
292281

293282
// check for secret token in the request
294-
if(isset($logCondition['shared_secret'])) {
283+
if (isset($logCondition['shared_secret'])) {
295284
$request = \OC::$server->getRequest();
296285

297286
// if token is found in the request change set the log condition to satisfied
298-
if($request && hash_equals($logCondition['shared_secret'], $request->getParam('log_secret', ''))) {
287+
if ($request && hash_equals($logCondition['shared_secret'], $request->getParam('log_secret', ''))) {
299288
$this->logConditionSatisfied = true;
300289
}
301290
}
302291

303292
// check for user
304-
if(isset($logCondition['users'])) {
293+
if (isset($logCondition['users'])) {
305294
$user = \OC::$server->getUserSession()->getUser();
306295

307296
// if the user matches set the log condition to satisfied
308-
if($user !== null && in_array($user->getUID(), $logCondition['users'], true)) {
297+
if ($user !== null && in_array($user->getUID(), $logCondition['users'], true)) {
309298
$this->logConditionSatisfied = true;
310299
}
311300
}
312301
}
313302
}
314303

315304
// if log condition is satisfied change the required log level to DEBUG
316-
if($this->logConditionSatisfied) {
317-
$minLevel = Util::DEBUG;
305+
if ($this->logConditionSatisfied) {
306+
return Util::DEBUG;
318307
}
319308

320-
if ($level >= $minLevel) {
321-
$logger = $this->logger;
322-
call_user_func([$logger, 'write'], $app, $message, $level);
309+
if (isset($context['app'])) {
310+
$logCondition = $this->config->getValue('log.condition', []);
311+
$app = $context['app'];
312+
313+
/**
314+
* check log condition based on the context of each log message
315+
* once this is met -> change the required log level to debug
316+
*/
317+
if (!empty($logCondition)
318+
&& isset($logCondition['apps'])
319+
&& in_array($app, $logCondition['apps'], true)) {
320+
return Util::DEBUG;
321+
}
322+
}
323+
324+
return min($this->config->getValue('loglevel', Util::WARN), Util::FATAL);
325+
}
326+
327+
private function filterTrace(array $trace) {
328+
$sensitiveValues = [];
329+
$trace = array_map(function (array $traceLine) use (&$sensitiveValues) {
330+
foreach ($this->methodsWithSensitiveParameters as $sensitiveMethod) {
331+
if (strpos($traceLine['function'], $sensitiveMethod) !== false) {
332+
$sensitiveValues = array_unique(array_merge($sensitiveValues, $traceLine['args']));
333+
$traceLine['args'] = ['*** sensitive parameters replaced ***'];
334+
return $traceLine;
335+
}
336+
}
337+
return $traceLine;
338+
}, $trace);
339+
return array_map(function (array $traceLine) use ($sensitiveValues) {
340+
$traceLine['args'] = $this->removeValuesFromArgs($traceLine['args'], $sensitiveValues);
341+
return $traceLine;
342+
}, $trace);
343+
}
344+
345+
private function removeValuesFromArgs($args, $values) {
346+
foreach($args as &$arg) {
347+
if (in_array($arg, $values, true)) {
348+
$arg = '*** sensitive parameter replaced ***';
349+
} else if (is_array($arg)) {
350+
$arg = $this->removeValuesFromArgs($arg, $values);
351+
}
323352
}
353+
return $args;
324354
}
325355

326356
/**
@@ -332,26 +362,35 @@ public function log(int $level, string $message, array $context = []) {
332362
* @since 8.2.0
333363
*/
334364
public function logException(\Throwable $exception, array $context = []) {
335-
$level = Util::ERROR;
336-
if (isset($context['level'])) {
337-
$level = $context['level'];
338-
unset($context['level']);
339-
}
365+
$app = $context['app'] ?? 'no app in context';
366+
$level = $context['level'] ?? Util::ERROR;
367+
340368
$data = [
369+
'CustomMessage' => $context['message'] ?? '--',
341370
'Exception' => get_class($exception),
342371
'Message' => $exception->getMessage(),
343372
'Code' => $exception->getCode(),
344-
'Trace' => $exception->getTraceAsString(),
373+
'Trace' => $this->filterTrace($exception->getTrace()),
345374
'File' => $exception->getFile(),
346375
'Line' => $exception->getLine(),
347376
];
348-
$data['Trace'] = preg_replace('!(' . implode('|', $this->methodsWithSensitiveParameters) . ')\(.*\)!', '$1(*** sensitive parameters replaced ***)', $data['Trace']);
349377
if ($exception instanceof HintException) {
350378
$data['Hint'] = $exception->getHint();
351379
}
352-
$msg = isset($context['message']) ? $context['message'] : 'Exception';
353-
$msg .= ': ' . json_encode($data);
354-
$this->log($level, $msg, $context);
380+
381+
$minLevel = $this->getLogLevel($context);
382+
383+
array_walk($context, [$this->normalizer, 'format']);
384+
385+
if ($level >= $minLevel) {
386+
if ($this->logger === File::class) {
387+
call_user_func([$this->logger, 'write'], $app, $data, $level);
388+
} else {
389+
$entry = json_encode($data, JSON_PARTIAL_OUTPUT_ON_ERROR);
390+
call_user_func([$this->logger, 'write'], $app, $entry, $level);
391+
}
392+
}
393+
355394
$context['level'] = $level;
356395
if (!is_null($this->crashReporters)) {
357396
$this->crashReporters->delegateReport($exception, $context);

‎lib/private/Log/File.php‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -72,7 +72,7 @@ public static function init() {
7272
/**
7373
* write a message in the log
7474
* @param string $app
75-
* @param string $message
75+
* @param string|array $message
7676
* @param int $level
7777
*/
7878
public static function write($app, $message, $level) {

‎tests/lib/LoggerTest.php‎

Lines changed: 20 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -96,9 +96,12 @@ public function testDetectlogin($user, $password) {
9696

9797
$logLines = $this->getLogs();
9898
foreach($logLines as $logLine) {
99+
if (is_array($logLine)) {
100+
$logLine = json_encode($logLine);
101+
}
99102
$this->assertNotContains($user, $logLine);
100103
$this->assertNotContains($password, $logLine);
101-
$this->assertContains('login(*** sensitive parameters replaced ***)', $logLine);
104+
$this->assertContains('*** sensitive parameters replaced ***', $logLine);
102105
}
103106
}
104107

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

116119
$logLines = $this->getLogs();
117120
foreach($logLines as $logLine) {
121+
if (is_array($logLine)) {
122+
$logLine = json_encode($logLine);
123+
}
118124
$this->assertNotContains($user, $logLine);
119125
$this->assertNotContains($password, $logLine);
120-
$this->assertContains('checkPassword(*** sensitive parameters replaced ***)', $logLine);
126+
$this->assertContains('*** sensitive parameters replaced ***', $logLine);
121127
}
122128
}
123129

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

135141
$logLines = $this->getLogs();
136142
foreach($logLines as $logLine) {
143+
if (is_array($logLine)) {
144+
$logLine = json_encode($logLine);
145+
}
137146
$this->assertNotContains($user, $logLine);
138147
$this->assertNotContains($password, $logLine);
139-
$this->assertContains('validateUserPass(*** sensitive parameters replaced ***)', $logLine);
148+
$this->assertContains('*** sensitive parameters replaced ***', $logLine);
140149
}
141150
}
142151

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

154163
$logLines = $this->getLogs();
155164
foreach($logLines as $logLine) {
165+
if (is_array($logLine)) {
166+
$logLine = json_encode($logLine);
167+
}
156168
$this->assertNotContains($user, $logLine);
157169
$this->assertNotContains($password, $logLine);
158-
$this->assertContains('tryLogin(*** sensitive parameters replaced ***)', $logLine);
170+
$this->assertContains('*** sensitive parameters replaced ***', $logLine);
159171
}
160172
}
161173

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

178190
$logLines = $this->getLogs();
179191
foreach($logLines as $logLine) {
192+
if (is_array($logLine)) {
193+
$logLine = json_encode($logLine);
194+
}
180195
$log = explode('\n', $logLine);
181196
unset($log[1]); // Remove `testDetectclosure(` because we are not testing this here, but the closure on stack trace 0
182197
$logLine = implode('\n', $log);
183198

184199
$this->assertNotContains($user, $logLine);
185200
$this->assertNotContains($password, $logLine);
186-
$this->assertContains('{closure}(*** sensitive parameters replaced ***)', $logLine);
201+
$this->assertContains('*** sensitive parameters replaced ***', $logLine);
187202
}
188203
}
189204

0 commit comments

Comments
 (0)