[stable10] Ability to log extra fields + trigger event when logging

lib/private/Log.php

@@ -37,6 +37,8 @@
 use \OCP\ILogger;
 use OCP\IUserSession;
 use OCP\Util;
+use Symfony\Component\EventDispatcher\GenericEvent;
+use Symfony\Component\EventDispatcher\EventDispatcherInterface;
 
 /**
  * logging utilities
@@ -56,12 +58,22 @@ class Log implements ILogger {
 	/** @var SystemConfig */
 	private $config;
 
+	/** @var EventDispatcherInterface */
+	private $eventDispatcher;
+
 	/** @var boolean|null cache the result of the log condition check for the request */
 	private $logConditionSatisfied = null;
 
 	/** @var Normalizer */
 	private $normalizer;
 
+	/**
+	 * Flag whether we are within the event block
+	 *
+	 * @var bool
+	 */
+	private $inEvent = false;
+
 	protected $methodsWithSensitiveParameters = [
 		// Session/User
 		'login',
@@ -96,8 +108,14 @@ class Log implements ILogger {
 	 * @param string $logger The logger that should be used
 	 * @param SystemConfig $config the system config object
 	 * @param null $normalizer
+	 * @param EventDispatcherInterface $eventDispatcher event dispatcher
 	 */
-	public function __construct($logger = null, SystemConfig $config = null, $normalizer = null) {
+	public function __construct(
+		$logger = null,
+		SystemConfig $config = null,
+		$normalizer = null,
+		EventDispatcherInterface $eventDispatcher = null
+	) {
 		// FIXME: Add this for backwards compatibility, should be fixed at some point probably
 		if($config === null) {
 			$config = \OC::$server->getSystemConfig();
@@ -118,6 +136,12 @@ public function __construct($logger = null, SystemConfig $config = null, $normal
 			$this->normalizer = $normalizer;
 		}
 
+		if ($eventDispatcher === null) {
+			$this->eventDispatcher = \OC::$server->getEventDispatcher();
+		} else {
+			$this->eventDispatcher = $eventDispatcher;
+		}
+
 	}
 
 	/**
@@ -236,6 +260,11 @@ public function log($level, $message, array $context = []) {
 		}
 		$logConditionFile = null;
 
+		$extraFields = [];
+		if (isset($context['extraFields'])) {
+			$extraFields = $context['extraFields'];
+			unset($context['extraFields']);
+		}
 		array_walk($context, [$this->normalizer, 'format']);
 
 		if (isset($context['app'])) {
@@ -268,7 +297,7 @@ public function log($level, $message, array $context = []) {
 		}
 
 		// interpolate replacement values into the message and return
-		$message = strtr($message, $replace);
+		$formattedMessage = strtr($message, $replace);
 
 		/**
 		 * check for a special log condition - this enables an increased log on
@@ -319,10 +348,45 @@ public function log($level, $message, array $context = []) {
 			$minLevel = Util::DEBUG;
 		}
 
+		$skipEvents = false;
+		// avoid infinite loop in case an event handler logs something
+		if ($this->inEvent) {
+			$skipEvents = true;
+		}
+
+		$eventArgs = [
+			'app' => $app,
+			'loglevel' => $level,
+			'message' => $message,
+			'formattedMessage' => $formattedMessage,
+			'context' => $context,
+			'extraFields' => $extraFields,
+		];
+
+		// note: regardless of log level we let listeners receive messages
+		$this->inEvent = true;
+		if (!$skipEvents) {
+			$event = new GenericEvent(null);
+			$event->setArguments($eventArgs);
+			$this->eventDispatcher->dispatch('log.beforewrite', $event);
+		}
+
 		if ($level >= $minLevel) {
 			$logger = $this->logger;
-			call_user_func([$logger, 'write'], $app, $message, $level, $logConditionFile);
+			// check if logger supports extra fields
+			if (!empty($extraFields) && is_callable($logger, 'writeExtra')) {
+				call_user_func([$logger, 'writeExtra'], $app, $formattedMessage, $level, $logConditionFile, $extraFields);
+			} else {
+				call_user_func([$logger, 'write'], $app, $formattedMessage, $level, $logConditionFile);
+			}
+		}
+
+		if (!$skipEvents) {
+			$event = new GenericEvent(null);
+			$event->setArguments($eventArgs);
+			$this->eventDispatcher->dispatch('log.afterwrite', $event);
 		}
+		$this->inEvent = false;
 	}
 
 	/**

lib/private/Log/Owncloud.php

@@ -70,6 +70,10 @@ public static function init() {
 	 * @param string conditionalLogFile
 	 */
 	public static function write($app, $message, $level, $conditionalLogFile = null) {
+		return self::writeExtra($app, $message, $level, $conditionalLogFile, []);
+	}
+
+	public static function writeExtra($app, $message, $level, $conditionalLogFile, $extraFields = []) {
 		$config = \OC::$server->getSystemConfig();
 
 		// default to ISO8601
@@ -110,6 +114,12 @@ public static function write($app, $message, $level, $conditionalLogFile = null)
 			'url',
 			'message'
 		);
+
+		if (!empty($extraFields)) {
+			// augment with additional fields
+			$entry = array_merge($entry, $extraFields);
+		}
+
 		$entry = json_encode($entry);
 		if (!is_null($conditionalLogFile)) {
 			if ($conditionalLogFile[0] !== '/') {

tests/lib/LoggerTest.php

@@ -12,6 +12,9 @@
 use OCP\IConfig;
 use OCP\IUserSession;
 use OCP\Util;
+use Symfony\Component\EventDispatcher\EventDispatcherInterface;
+use Symfony\Component\EventDispatcher\EventDispatcher;
+use Symfony\Component\EventDispatcher\GenericEvent;
 
 class LoggerTest extends TestCase {
 	/** @var \OCP\ILogger */
@@ -21,6 +24,9 @@ class LoggerTest extends TestCase {
 	/** @var IConfig | \PHPUnit_Framework_MockObject_MockObject */
 	private $config;
 
+	/** @var EventDispatcherInterface | \PHPUnit_Framework_MockObject_MockObject */
+	private $eventDispatcher;
+
 	protected function setUp() {
 		parent::setUp();
 
@@ -29,7 +35,8 @@ protected function setUp() {
 			'\OC\SystemConfig')
 			->disableOriginalConstructor()
 			->getMock();
-		$this->logger = new Log('Test\LoggerTest', $this->config);
+		$this->eventDispatcher = new EventDispatcher();
+		$this->logger = new Log('Test\LoggerTest', $this->config, null, $this->eventDispatcher);
 	}
 
 	public function testInterpolation() {
@@ -107,6 +114,11 @@ public static function write($app, $message, $level) {
 		self::$logs[]= "$level $message";
 	}
 
+	public static function writeExtra($app, $message, $level, $logConditionFile, $extraFields) {
+		$encodedFields = json_encode($extraFields);
+		self::$logs[]= "$level $message fields=$encodedFields";
+	}
+
 	public function userAndPasswordData() {
 		return [
 			['abc', 'def'],
@@ -197,4 +209,75 @@ public function testDetectloginWithPassword($user, $password) {
 		}
 	}
 
+	public function testExtraFields() {
+		$extraFields = [
+			'one' => 'un',
+			'two' => 'deux',
+			'three' => 'trois',
+		];
+
+		// with fields calls "writeExtra"
+		$this->logger->info(
+			'extra fields test', [
+				'extraFields' => $extraFields
+			]
+		);
+
+		// without fields calls "write"
+		$this->logger->info('no fields');
+
+		$logLines = $this->getLogs();
+
+		$this->assertEquals('1 extra fields test fields={"one":"un","two":"deux","three":"trois"}', $logLines[0]);
+		$this->assertEquals('1 no fields', $logLines[1]);
+	}
+
+	public function testEvents() {
+		$this->config->expects($this->any())
+			->method('getValue')
+			->will(($this->returnValueMap([
+				['loglevel', Util::WARN, Util::WARN],
+			])));
+
+		$beforeWriteEvent = null;
+		$this->eventDispatcher->addListener(
+			'log.beforewrite',
+			function(GenericEvent $event) use (&$beforeWriteEvent) {
+				$beforeWriteEvent = $event;
+			}
+		);
+		$afterWriteEvent = null;
+		$this->eventDispatcher->addListener(
+			'log.afterwrite',
+			function(GenericEvent $event) use (&$afterWriteEvent) {
+				$afterWriteEvent = $event;
+			}
+		);
+
+		$this->logger->debug(
+			'some {test} message', [
+				'app' => 'testapp',
+				'test' => 'replaced',
+				'extraFields' => ['extra' => 'one'],
+			]
+		);
+
+		$this->assertNotNull($beforeWriteEvent, 'before event was triggered');
+		$this->assertNotNull($afterWriteEvent, 'before event was triggered');
+
+		$expectedArgs = [
+			'app' => 'testapp',
+			'loglevel' => Util::DEBUG,
+			'message' => 'some {test} message',
+			'formattedMessage' => 'some replaced message',
+			'context' => [
+				'app' => 'testapp',
+				'test' => 'replaced',
+			],
+			'extraFields' => ['extra' => 'one'],
+		];
+
+		$this->assertEquals($expectedArgs, $beforeWriteEvent->getArguments(), 'before event arguments match');
+		$this->assertEquals($expectedArgs, $afterWriteEvent->getArguments(), 'after event arguments match');
+	}
 }