Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Separate audit logs from server logs. #27443

Merged
merged 1 commit into from
Mar 24, 2017
+80 −29
Merged

Separate audit logs from server logs. #27443

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
20 changes: 16 additions & 4 deletions config/config.sample.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -602,13 +602,25 @@
* this condition is met
* - ``apps``: if the log message is invoked by one of the specified apps,
* this condition is met
* - ``logfile``: the log message invoked by the specified apps get redirected to
* this logfile, this condition is met
* Note: Not applicapable when using syslog.
*
* Defaults to an empty array.
*/
'log.condition' => [
'shared_secret' => '57b58edb6637fe3059b3595cf9c41b9',
'users' => ['sample-user'],
'apps' => ['files'],
'log.conditions' => [
[
'shared_secret' => '57b58edb6637fe3059b3595cf9c41b9',
'users' => ['user1'],
'apps' => ['files_texteditor'],
'logfile' => '/tmp/test.log'
],
[
'shared_secret' => '57b58edb6637fe3059b3595cf9c41b9',
'users' => ['user1'],
'apps' => ['gallery'],
'logfile' => '/tmp/gallery.log'
],
],

/**
Expand Down
59 changes: 37 additions & 22 deletions lib/private/Log.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -230,7 +230,11 @@ public function debug($message, array $context = []) {
*/
public function log($level, $message, array $context = []) {
$minLevel = min($this->config->getValue('loglevel', Util::WARN), Util::FATAL);
$logCondition = $this->config->getValue('log.condition', []);
$logConditions = $this->config->getValue('log.conditions', []);
if (empty($logConditions)) {
$logConditions[] = $this->config->getValue('log.condition', []);
}
$logConditionFile = null;

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

Expand All @@ -241,10 +245,17 @@ public function log($level, $message, array $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;
if(!empty($logConditions)) {
foreach ($logConditions as $logCondition) {
if(!empty($logCondition['apps'])
&& in_array($app, $logCondition['apps'], true)) {
$minLevel = Util::DEBUG;
if (!empty($logCondition['logfile'])) {
$logConditionFile = $logCondition['logfile'];
break;
}
}
}
}

} else {
Expand All @@ -266,25 +277,29 @@ public function log($level, $message, array $context = []) {
if($this->logConditionSatisfied === null) {
// default to false to just process this once per request
$this->logConditionSatisfied = false;
if(!empty($logCondition)) {

// check for secret token in the request
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'))) {
$this->logConditionSatisfied = true;
if(!empty($logConditions)) {
foreach ($logConditions as $logCondition) {

// check for secret token in the request
if (!empty($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'))) {
$this->logConditionSatisfied = true;
break;
}
}
}

// check for user
if(isset($logCondition['users'])) {
$user = \OC::$server->getUserSession()->getUser();
// check for user
if (!empty($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)) {
$this->logConditionSatisfied = true;
// if the user matches set the log condition to satisfied
if ($user !== null && in_array($user->getUID(), $logCondition['users'], true)) {
$this->logConditionSatisfied = true;
break;
}
}
}
}
Expand All @@ -297,7 +312,7 @@ public function log($level, $message, array $context = []) {

if ($level >= $minLevel) {
$logger = $this->logger;
call_user_func([$logger, 'write'], $app, $message, $level);
call_user_func([$logger, 'write'], $app, $message, $level, $logConditionFile);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does it make sense that the "global" logger (aka, this class) tells the specific loggers where they have to write? Is it useful for any other logger (syslog, for example)?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

impact on syslog - this was one of my questions above: #27443 (comment)
Not to complain if so, but necessay to know and document.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

AFAICT the syslog logger will ignore the logfile condition and always log to syslog.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Raises the question: shall this be enabled for syslog too, would that make sense?

In any case it needs a note in config.sample.php and/or the documentation.
aka: Not applicapable when using syslog, or This also splits logs when using syslog

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@butonic can you check if logging to syslog will ignore logfile conditions?
This is important regarding proper documentation.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd move the checks for the different logs files directly into the ownCloud log and keep the same "interface" for all the loggers. Basically, the ownCloud logger would read the log.conditions configuration and initialize itself properly (if possible).

}
}

Expand Down
12 changes: 9 additions & 3 deletions lib/private/Log/Owncloud.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -67,8 +67,9 @@ public static function init() {
* @param string $app
* @param string $message
* @param int $level
* @param string conditionalLogFile
*/
public static function write($app, $message, $level) {
public static function write($app, $message, $level, $conditionalLogFile = null) {
$config = \OC::$server->getSystemConfig();

// default to ISO8601
Expand Down Expand Up @@ -110,8 +111,13 @@ public static function write($app, $message, $level) {
'user'
);
$entry = json_encode($entry);
$handle = @fopen(self::$logFile, 'a');
@chmod(self::$logFile, 0640);
if (!is_null($conditionalLogFile)) {
$handle = @fopen($conditionalLogFile, 'a');
@chmod($conditionalLogFile, 0640);
} else {
$handle = @fopen(self::$logFile, 'a');
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

wow, did we really do a fopen on the log file for every single entry ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yah.

Copy link
Member

@butonic butonic Mar 22, 2017 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

hm what would happen if we keep the handle open until the request ends? I can only guess how that behaves when multiple processes write log messages. hmmm monolog also uses the file handle for the whole request (unless you call close()): https://github.com/Seldaek/monolog/blob/master/src/Monolog/Handler/StreamHandler.php#L95-L111 It seems the underlying fwrite implementation is thread safe: http://stackoverflow.com/a/2220574

so we should be able to optimize our log writing ... @mrow4a ?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

quoting official php documentation:

(http://php.net/manual/en/function.fwrite.php)

If handle was fopen()ed in append mode, fwrite()s are atomic (unless the size of string exceeds the filesystem's block size, on some platforms, and as long as the file is on a local filesystem). That is, there is no need to flock() a resource before calling fwrite(); all of the data will be written without interruption.

(http://php.net/manual/en/function.fseek.php)

If you have opened the file in append (a or a+) mode, any data you write to the file will always be appended, regardless of the file position, and the result of calling fseek() will be undefined.

I'd keep the file opened and lock the file when writing (we can't guarantee the log entry to have less than 1k). In addition I've read somewhere the writes over NFS aren't atomic, so that another reason to lock the file.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

wouldn't that block other requests from writing log messages until the lock is released?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes, but hopefully it won't be dramatic. The flow would be: open file to append and when we want to write a log entry, lock the file for writing - write - unlock. There is no need to open and close the file over and over.

We could add an option to use locks or not over the log file if there is a noticeable performance impact. I expect some overhead, but hopefully not much.

Copy link
Member

@butonic butonic Mar 22, 2017 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hm I fear locking will kill performance. What does google say? The log4php guys have a benchmark ... it is from 2009, but we could rerun it on todays php to see the numbers: https://www.grobmeier.de/performance-ofnonblocking-write-to-files-via-php-21082009.html

running 4 scripts in parralel in the browser with 100000 loops in my vm with php 5.6 on debian produces:

Execution with NOT closing the log file took 5.9572031497955 seconds
Execution with CLOSING the log after each write file took 17.085966825485 seconds
Execution with file_put_content took 16.009223937988 seconds
Execution with leaving the file open, but LOCKING and UNLOCKING it took 5.5897269248962 seconds
Execution with nonblocking stream took 6.125638961792 seconds
Execution with the error_log method took 14.576776981354 seconds

so I think locking is the way to go ... in a different pr.

@sharidas sorry for highjacking ..

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

so I think locking is the way to go ... in a different pr.

Yes, it's outside of scope for this PR. No need to change it right now.

@chmod(self::$logFile, 0640);
}
if ($handle) {
fwrite($handle, $entry."\n");
fclose($handle);
Expand Down
18 changes: 18 additions & 0 deletions tests/lib/LoggerTest.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -59,6 +59,24 @@ public function testAppCondition() {
$this->assertEquals($expected, $this->getLogs());
}

public function testAppLogCondition() {
$this->config->expects($this->any())
->method('getValue')
->will(($this->returnValueMap([
['loglevel', Util::WARN, Util::WARN],
['log.conditions', [], [['apps' => ['files'], 'logfile' => '/tmp/test.log']]]
])));
$logger = $this->logger;

$logger->info('Don\'t display info messages');
$logger->info('Show info messages of files app', ['app' => 'files']);

$expected = [
'1 Show info messages of files app',
];
$this->assertEquals($expected, $this->getLogs());
}

private function getLogs() {
return self::$logs;
}
Expand Down