Merge pull request #8 from OS2web/feature/audit-logging-performance

Added queue logic to enhance performance

.github/workflows/pr.yml

@@ -23,7 +23,7 @@ jobs:
     runs-on: ubuntu-latest
     strategy:
       matrix:
-        php-versions: [ '8.1' ]
+        php-versions: [ '8.3' ]
         dependency-version: [ prefer-lowest, prefer-stable ]
     steps:
       - uses: actions/checkout@master
@@ -55,7 +55,7 @@ jobs:
     runs-on: ubuntu-latest
     strategy:
       matrix:
-        php-versions: [ '8.1' ]
+        php-versions: [ '8.3' ]
     steps:
       - uses: actions/checkout@master
       - name: Setup PHP, with composer and extensions
@@ -87,7 +87,7 @@ jobs:
     runs-on: ubuntu-latest
     strategy:
       matrix:
-        php-versions: [ '8.1' ]
+        php-versions: [ '8.3' ]
     steps:
       - uses: actions/checkout@master
       - name: Setup PHP, with composer and extensions

CHANGELOG.md

@@ -8,6 +8,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+- Added queue logic to enhance performance.
 - Add new module to track user accessing webform submissions.
 - Added remote ip to all log lines.
 

README.md

@@ -12,6 +12,10 @@ These logging providers are designed using Drupal's plugin APIs. Consequently,
 it opens up possibilities for creating new AuditLogger plugins within other
 modules, thus enhancing the functionality of this audit logging.
 
+For performance purposes we use a queue system. This avoids hindering
+performance more than necessary as the actual logging is done async. Furthermore,
+this allows for retries in case any audit log plugins should fail.
+
 ## Installation
 
 Enable the module and go to the modules setting page at
@@ -47,3 +51,24 @@ logger as shown below:
 $msg = sprintf('Fetch personal data from service with parameter: %s', $param);
 $this->auditLogger->info('Lookup', $msg);
 ```
+
+### Queue
+
+The actual logging is handled by jobs in an [Advanced
+Queue](https://www.drupal.org/project/advancedqueue) queue.
+
+The queue, OS2Web audit (`os2web_audit`), must be
+processed by a server `cron` job, e.g.
+
+```sh
+drush advancedqueue:queue:process os2web_audit
+```
+
+List the queue (and all other queues) with
+
+```sh
+drush advancedqueue:queue:list
+```
+
+or go to `/admin/config/system/queues/jobs/os2web_audit` for a
+graphical overview of jobs in the queue.

composer.json

@@ -18,6 +18,7 @@
     "require": {
         "ext-curl": "*",
         "php": "^8.1",
+        "drupal/advancedqueue": "^1.2",
         "drush/drush": "^11.5|^12.5"
     },
     "require-dev": {

config/install/advancedqueue.advancedqueue_queue.os2web_audit.yml

@@ -0,0 +1,10 @@
+status: true
+dependencies: {  }
+id: os2web_audit
+label: os2web_audit
+backend: database
+backend_configuration:
+  lease_time: 300
+processor: daemon
+processing_time: 90
+locked: false

os2web_audit.services.yml

@@ -5,4 +5,4 @@ services:
 
   os2web_audit.logger:
     class: Drupal\os2web_audit\Service\Logger
-    arguments: ['@plugin.manager.os2web_audit_logger', '@config.factory', '@current_user', '@logger.factory', '@request_stack']
+    arguments: ['@plugin.manager.os2web_audit_logger', '@config.factory', '@current_user', '@logger.factory', '@request_stack', '@entity_type.manager']

src/Plugin/AdvancedQueue/JobType/LogMessages.php

@@ -0,0 +1,69 @@
+<?php
+
+namespace Drupal\os2web_audit\Plugin\AdvancedQueue\JobType;
+
+use Drupal\Component\Plugin\Exception\PluginException;
+use Drupal\Core\Plugin\ContainerFactoryPluginInterface;
+use Drupal\advancedqueue\Job;
+use Drupal\advancedqueue\JobResult;
+use Drupal\advancedqueue\Plugin\AdvancedQueue\JobType\JobTypeBase;
+use Drupal\os2web_audit\Exception\AuditException;
+use Drupal\os2web_audit\Exception\ConnectionException;
+use Drupal\os2web_audit\Service\Logger;
+use Symfony\Component\DependencyInjection\ContainerInterface;
+
+/**
+ * Log messages job.
+ *
+ * @AdvancedQueueJobType(
+ *   id = "Drupal\os2web_audit\Plugin\AdvancedQueue\JobType\LogMessages",
+ *   label = @Translation("Audit Log messages"),
+ * )
+ */
+class LogMessages extends JobTypeBase implements ContainerFactoryPluginInterface {
+
+  /**
+   * {@inheritdoc}
+   *
+   * @phpstan-param array<string, mixed> $configuration
+   */
+  public static function create(ContainerInterface $container, array $configuration, $plugin_id, $plugin_definition) {
+    return new static(
+      $configuration,
+      $plugin_id,
+      $plugin_definition,
+      $container->get('os2web_audit.logger'),
+    );
+  }
+
+  /**
+   * {@inheritdoc}
+   *
+   * @phpstan-param array<string, mixed> $configuration
+   */
+  public function __construct(
+    array $configuration,
+    $plugin_id,
+    $plugin_definition,
+    private readonly Logger $logger,
+  ) {
+    parent::__construct($configuration, $plugin_id, $plugin_definition);
+  }
+
+  /**
+   * Processes the LogMessages job.
+   */
+  public function process(Job $job): JobResult {
+    $payload = $job->getPayload();
+
+    try {
+      $this->logger->log($payload['type'], $payload['timestamp'], $payload['line'], $payload['plugin_id'], $payload['metadata']);
+
+      return JobResult::success();
+    }
+    catch (PluginException | ConnectionException | AuditException $e) {
+      return JobResult::failure($e->getMessage());
+    }
+  }
+
+}

src/Service/Logger.php

@@ -2,14 +2,14 @@
 
 namespace Drupal\os2web_audit\Service;
 
-use Drupal\Component\Plugin\Exception\PluginException;
 use Drupal\Core\Config\ConfigFactoryInterface;
+use Drupal\Core\Entity\EntityTypeManagerInterface;
 use Drupal\Core\Logger\LoggerChannelFactoryInterface;
 use Drupal\Core\Session\AccountProxyInterface;
-use Drupal\os2web_audit\Exception\AuditException;
-use Drupal\os2web_audit\Exception\ConnectionException;
+use Drupal\advancedqueue\Job;
 use Drupal\os2web_audit\Form\PluginSettingsForm;
 use Drupal\os2web_audit\Form\SettingsForm;
+use Drupal\os2web_audit\Plugin\AdvancedQueue\JobType\LogMessages;
 use Drupal\os2web_audit\Plugin\LoggerManager;
 use Symfony\Component\HttpFoundation\RequestStack;
 
@@ -20,12 +20,16 @@
  */
 class Logger {
 
+  const string OS2WEB_AUDIT_QUEUE_ID = 'os2web_audit';
+  const string OS2WEB_AUDIT_LOGGER_CHANNEL = 'os2web_audit_info';
+
   public function __construct(
     private readonly LoggerManager $loggerManager,
     private readonly ConfigFactoryInterface $configFactory,
     private readonly AccountProxyInterface $currentUser,
     private readonly LoggerChannelFactoryInterface $watchdog,
     private readonly RequestStack $requestStack,
+    private readonly EntityTypeManagerInterface $entityTypeManager,
   ) {
   }
 
@@ -43,7 +47,7 @@ public function __construct(
    *   Additional metadata for the log message. Default is an empty array.
    */
   public function info(string $type, string $line, bool $logUser = TRUE, array $metadata = []): void {
-    $this->log($type, time(), $line, $logUser, $metadata + ['level' => 'info']);
+    $this->createLoggingJob($type, time(), $line, $logUser, $metadata + ['level' => 'info']);
   }
 
   /**
@@ -60,11 +64,11 @@ public function info(string $type, string $line, bool $logUser = TRUE, array $me
    *   Additional metadata for the log message. Default is an empty array.
    */
   public function error(string $type, string $line, bool $logUser = TRUE, array $metadata = []): void {
-    $this->log($type, time(), $line, $logUser, $metadata + ['level' => 'error']);
+    $this->createLoggingJob($type, time(), $line, $logUser, $metadata + ['level' => 'error']);
   }
 
   /**
-   * Logs a message using a plugin-specific logger.
+   * Creates and enqueues logging job.
    *
    * @param string $type
    *   The type of event to log (auth, lookup etc.)
@@ -78,11 +82,9 @@ public function error(string $type, string $line, bool $logUser = TRUE, array $m
    * @param array<string, string> $metadata
    *   Additional metadata for the log message. Default is an empty array.
    */
-  private function log(string $type, int $timestamp, string $line, bool $logUser = FALSE, array $metadata = []): void {
-    $config = $this->configFactory->get(SettingsForm::$configName);
-    $plugin_id = $config->get('provider') ?? SettingsForm::OS2WEB_AUDIT_DEFUALT_PROVIDER;
-    $configuration = $this->configFactory->get(PluginSettingsForm::getConfigName())->get($plugin_id);
+  private function createLoggingJob(string $type, int $timestamp, string $line, bool $logUser = FALSE, array $metadata = []): void {
 
+    // Enhance logging data with current user and current request information.
     if ($logUser) {
       // Add user id to the log message metadata.
       $metadata['userId'] = $this->currentUser->getEmail();
@@ -95,25 +97,57 @@ private function log(string $type, int $timestamp, string $line, bool $logUser =
       $line .= sprintf(' Remote ip: %s', $ip_address);
     }
 
+    $config = $this->configFactory->get(SettingsForm::$configName);
+    $plugin_id = $config->get('provider') ?? SettingsForm::OS2WEB_AUDIT_DEFUALT_PROVIDER;
+
+    $payload = [
+      'type' => $type,
+      'timestamp' => $timestamp,
+      'line' => $line,
+      'plugin_id' => $plugin_id,
+      'metadata' => $metadata,
+    ];
+
     try {
-      /** @var \Drupal\os2web_audit\Plugin\AuditLogger\AuditLoggerInterface $logger */
-      $logger = $this->loggerManager->createInstance($plugin_id, $configuration ?? []);
-      $logger->log($type, $timestamp, $line, $metadata);
-    }
-    catch (PluginException $e) {
-      $this->watchdog->get('os2web_audit')->error($e->getMessage());
+      $queueStorage = $this->entityTypeManager->getStorage('advancedqueue_queue');
+      /** @var \Drupal\advancedqueue\Entity\Queue $queue */
+      $queue = $queueStorage->load(self::OS2WEB_AUDIT_QUEUE_ID);
+
+      $job = Job::create(LogMessages::class, $payload);
+
+      $queue->enqueueJob($job);
     }
-    catch (AuditException | ConnectionException $e) {
-      // Change metadata into string.
-      $data = implode(', ', array_map(function ($key, $value) {
-        return $key . " => " . $value;
-      }, array_keys($metadata), $metadata));
-
-      // Fallback to send log message info watchdog.
-      $msg = sprintf("Plugin: %s, Type: %s, Msg: %s, Metadata: %s", $e->getPluginName(), $type, $line, $data);
-      $this->watchdog->get('os2web_audit')->info($msg);
-      $this->watchdog->get('os2web_audit_error')->error($e->getMessage());
+    catch (\Exception $exception) {
+      $this->watchdog->get(self::OS2WEB_AUDIT_LOGGER_CHANNEL)->error(sprintf('Failed creating job: %s', $exception->getMessage()), $payload);
     }
+
+  }
+
+  /**
+   * Logs a message using a plugin-specific logger.
+   *
+   * @param string $type
+   *   The type of event to log (auth, lookup etc.)
+   * @param int $timestamp
+   *   The timestamp for the log message.
+   * @param string $line
+   *   The log message.
+   * @param string $plugin_id
+   *   The logging plugin id.
+   * @param array<string, string> $metadata
+   *   Additional metadata for the log message. Default is an empty array.
+   *
+   * @throws \Drupal\Component\Plugin\Exception\PluginException
+   * @throws \Drupal\os2web_audit\Exception\ConnectionException
+   * @throws \Drupal\os2web_audit\Exception\AuditException
+   */
+  public function log(string $type, int $timestamp, string $line, string $plugin_id, array $metadata = []): void {
+
+    $configuration = $this->configFactory->get(PluginSettingsForm::getConfigName())->get($plugin_id);
+
+    /** @var \Drupal\os2web_audit\Plugin\AuditLogger\AuditLoggerInterface $logger */
+    $logger = $this->loggerManager->createInstance($plugin_id, $configuration ?? []);
+    $logger->log($type, $timestamp, $line, $metadata);
   }
 
 }