Issue #3252967 by mathilde_dumond: New sensor: response timing

config/schema/monitoring.schema.yml

@@ -370,3 +370,17 @@ monitoring.settings.commerce_turnover:
     commerce_order_currency:
       type: string
       label: 'Currency'
+
+monitoring.settings.response_time:
+  type: monitoring.settings_base
+  label: 'Response time'
+  mapping:
+    main_metric:
+      type: string
+      label: 'Main metric'
+    lines:
+      type: integer
+      label: 'Number of entries'
+    log_file:
+      type: string
+      label: 'Path to the log file for response times'

src/Plugin/monitoring/SensorPlugin/ResponseTimeSensorPlugin.php

+<?php
+
+namespace Drupal\monitoring\Plugin\monitoring\SensorPlugin;
+
+use Drupal\Component\Render\FormattableMarkup;
+use Drupal\Core\Form\FormStateInterface;
+use Drupal\monitoring\Result\SensorResultInterface;
+use Drupal\monitoring\SensorPlugin\SensorPluginBase;
+
+/**
+ * Monitors system load time.
+ *
+ * @SensorPlugin(
+ *   id = "response_time",
+ *   label = @Translation("Response time"),
+ *   description = @Translation("Monitors website response time."),
+ *   addable = TRUE
+ * )
+ */
+class ResponseTimeSensorPlugin extends SensorPluginBase {
+
+  /**
+   * {@inheritdoc}
+   */
+  public function buildConfigurationForm(array $form, FormStateInterface $form_state) {
+    $form = parent::buildConfigurationForm($form, $form_state);
+    $form['main_metric'] = [
+      '#type' => 'select',
+      '#title' => $this->t('Main monitored metric'),
+      '#options' => [
+        'average' => $this->t('Average'),
+        'percentile_90' => $this->t('90th percentile'),
+        'percentile_95' => $this->t('95th percentile'),
+      ],
+      '#default_value' => $this->sensorConfig->getSetting('main_metric'),
+      '#description' => $this->t('You can select which metric is used for the warning and critical sensors. All metrics are available in the log.'),
+      '#required' => TRUE,
+    ];
+    $form['lines'] = [
+      '#type' => 'number',
+      '#title' => $this->t('Number of entries assessed'),
+      '#default_value' => $this->sensorConfig->getSetting('lines'),
+      '#description' => $this->t('How many entries are assessed for this metric. The time frame that this represents depends on the overall traffic of the website.'),
+      '#required' => TRUE,
+    ];
+    $form['log_file'] = [
+      '#type' => 'textfield',
+      '#title' => $this->t('Location of the log file'),
+      '#default_value' => $this->sensorConfig->getSetting('log_file'),
+      '#description' => $this->t('File where the access time requests are logged (php.access.log).'),
+      '#required' => TRUE,
+    ];
+
+    return $form;
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function runSensor(SensorResultInterface $result) {
+    $time_response_data = $this->getTimeResponseData();
+    if (!$time_response_data['times']) {
+      $result->setStatus(SensorResultInterface::STATUS_WARNING);
+      $result->setMessage('Log file @filename is empty.', [
+        '@filename' => $this->sensorConfig->getSetting('log_file'),
+      ]);
+    }
+    else {
+      $setting = $this->sensorConfig->getSetting('main_metric');
+      $times = array_values($time_response_data['times']);
+      $average = (int) (array_sum($times) / count($times));
+      $percentile_90 = (int) $this->getPercentile($times, 90);
+      $percentile_95 = (int) $this->getPercentile($times, 95);
+      $result->setValue($$setting);
+      $result->addStatusMessage( 'Average: ' . $average . ' ms, 90%: ' . $percentile_90 . ' ms, 95%: ' . $percentile_95 . 'ms, start date: ' . $time_response_data['start']);
+    }
+  }
+
+  /**
+   * {@inheritdoc}
+   */
+  public function getDefaultConfiguration() {
+    return [
+      'caching_time' => 0,
+      'value_type' => 'number',
+      'settings' => [
+        'main_metric' => 'percentile_90',
+        'lines' => '1000',
+        'log_file' => '',
+      ],
+    ];
+  }
+
+  /**
+   * Gets the response time data.
+   *
+   * @return array
+   *   The response time data.
+   *
+   * @throws \Exception
+   *   Thrown when the log file cannot be found or read.
+   */
+  protected function getTimeResponseData(): array {
+    $lines = $this->sensorConfig->getSetting('lines');
+    $filename = $this->sensorConfig->getSetting('log_file');
+    if (!$filename) {
+      throw new \Exception(t('Log file not defined.'));
+    }
+    $data = $this->getEndOfFile($filename, $lines);
+
+    $start = explode(' ', $data[0])[0];
+    $times = [];
+    foreach ($data as $line) {
+      // 2020-05-07 00:17:04 GET 301 245.353 ms 16384 kB 36.68% /
+      if (preg_match('/(\d{4}-\d{2}-\d{2}).+ ([0-9\.]+) ms/', $line, $match)) {
+        $times[] = $match[2];
+      }
+    }
+    // Keeping raw data for further improvements.
+    return ['times' => $times, 'start' => $start, 'raw_data' => $lines];
+  }
+
+  /**
+   * Returns the value of the metric corresponding to the given percentile.
+   *
+   * @param array $array
+   *   Array of values.
+   * @param int $percentile
+   *   Which percentile to get (1 to 99).
+   *
+   * @return float|int|mixed
+   *   Percentile value.
+   */
+  protected function getPercentile(array $array, int $percentile) {
+    $percentile = min(100, max(0, $percentile));
+    $array = array_values($array);
+    sort($array);
+    $index = ($percentile / 100) * (count($array) - 1);
+    $fraction_part = $index - floor($index);
+    $int_part = floor($index);
+
+    $percentile = $array[$int_part];
+    $percentile += ($fraction_part > 0) ? $fraction_part * ($array[$int_part + 1] - $array[$int_part]) : 0;
+
+    return $percentile;
+  }
+
+  /**
+   * Returns an array with the n lines at the end of the file.
+   *
+   * @param string $filepath
+   *   Path of the file.
+   * @param int $lines
+   *   Number of lines.
+   *
+   * @return string[]
+   *   Array with the n lines at the end of the file.
+   *
+   * @throws \Exception
+   *   Thrown when the log file cannot be found or read.
+   */
+  protected function getEndOfFile(string $filepath, int $lines = 1) {
+    // From https://gist.github.com/lorenzos/1711e81a9162320fde20.
+    // https://stackoverflow.com/questions/15025875/what-is-the-best-way-to-read-last-lines-i-e-tail-from-a-file-using-php/15025877#15025877.
+
+    // Open file.
+    if (!file_exists($filepath)) {
+      throw new \Exception(new FormattableMarkup('Log file @filename not found.', [
+        '@filename' => $this->sensorConfig->getSetting('log_file'),
+      ]));
+    }
+    $f = fopen($filepath, "rb");
+
+    if ($f === FALSE) {
+      throw new \Exception(new FormattableMarkup('Log file @filename could not be read.', [
+        '@filename' => $this->sensorConfig->getSetting('log_file'),
+      ]));
+    }
+
+    $buffer = 4096;
+
+    // Jump to last character.
+    fseek($f, -1, SEEK_END);
+
+    // Read it and adjust line number if necessary.
+    // (Otherwise the result would be wrong
+    // if file doesn't end with a blank line).
+    if (fread($f, 1) != "\n") {
+      $lines -= 1;
+    }
+
+    // Start reading.
+    $output = '';
+    // While we would like more.
+    while (ftell($f) > 0 && $lines >= 0) {
+      // Figure out how far back we should jump.
+      $seek = min(ftell($f), $buffer);
+      // Do the jump (backwards, relative to where we are).
+      fseek($f, -$seek, SEEK_CUR);
+      // Read a chunk and prepend it to our output.
+      $output = ($chunk = fread($f, $seek)) . $output;
+      // Jump back to where we started reading.
+      fseek($f, -mb_strlen($chunk, '8bit'), SEEK_CUR);
+      // Decrease our line counter.
+      $lines -= substr_count($chunk, "\n");
+    }
+    // While we have too many lines.
+    // (Because of buffer size we might have read too many).
+    while ($lines++ < 0) {
+      // Find first newline and remove all text before that.
+      $output = substr($output, strpos($output, "\n") + 1);
+    }
+    // Close file and return.
+    fclose($f);
+    return explode("\n", trim($output));
+  }
+
+}

tests/fixtures/example.php.access.log

+2021-11-13T15:23:36Z GET 404 105.083 ms 12288 kB 47.58% /page1
+2021-11-13T15:36:54Z GET 304 13.879 ms 4096 kB 0.00% /page2
+2021-11-13T20:01:33Z GET 200 13.654 ms 4096 kB 0.00% /page2
+2021-11-14T01:36:38Z GET 404 1089.231 ms 26624 kB 41.31% /wordpress/page2
+2021-11-14T01:36:38Z GET 404 1131.606 ms 26624 kB 36.23% /wp/page2
+2021-11-14T01:36:40Z GET 404 95.854 ms 8192 kB 73.03% /blog
+2021-11-14T01:57:25Z GET 404 210.177 ms 22528 kB 57.09% /blog
+2021-11-14T05:00:44Z GET 200 3249.727 ms 40960 kB 19.39% /blog/article
+2021-11-14T09:14:25Z GET 200 1290.085 ms 34816 kB 29.46% /
+2021-11-14T11:24:07Z GET 200 500.919 ms 32768 kB 51.90% /
+2021-11-14T12:45:33Z GET 304 15.005 ms 4096 kB 0.00% /blog
+2021-11-14T14:24:40Z GET 200 901.131 ms 30720 kB 24.41% /sciences/article
+2021-11-14T15:09:38Z GET 200 258.484 ms 20480 kB 34.82% /
+2021-11-14T15:09:38Z GET 200 349.739 ms 26624 kB 45.75% /
+2021-11-14T20:11:30Z GET 200 7464.305 ms 67584 kB 24.52% /theme/psychology
+2021-11-14T23:44:01Z GET 200 64.338 ms 10240 kB 46.63% /blog
+2021-11-15T07:59:41Z GET 200 4971.045 ms 67584 kB 24.74% /
+2021-11-15T09:16:22Z GET 200 872.936 ms 30720 kB 25.20% /
+2021-11-15T09:16:23Z GET 200 6.872 ms 2048 kB 145.52% /
+2021-11-15T09:16:24Z POST 200 99.104 ms 2048 kB 20.18% /article
+2021-11-15T09:16:24Z GET 404 32.546 ms 4096 kB 92.18% /page-not-found
+2021-11-15T09:16:24Z GET 404 52.716 ms 2048 kB 37.94% /page-not-found
+2021-11-15T09:16:25Z GET 404 60.400 ms 10240 kB 49.67% /page42
+2021-11-15T09:16:26Z GET 200 27.083 ms 2048 kB 110.77% /blog
+2021-11-15T10:10:41Z GET 200 2463.837 ms 34816 kB 10.96% /economics/blog
+2021-11-15T12:33:52Z GET 200 20.222 ms 4096 kB 0.00% /

tests/src/Kernel/MonitoringResponseTimeSensorTest.php

+<?php
+
+namespace Drupal\Tests\monitoring\Kernel;
+
+use Drupal\monitoring\Entity\SensorConfig;
+
+/**
+ * Kernel tests for the monitoring response time plugin.
+ *
+ * @group monitoring
+ */
+class MonitoringResponseTimeSensorTest extends MonitoringUnitTestBase {
+
+  /**
+   * Test the response time sensor plugin.
+   */
+  public function testResponseTimeSensorPlugin() {
+    $sensor = SensorConfig::create([
+      'id' => 'response_time_test',
+      'label' => 'Response time',
+      'plugin_id' => 'response_time',
+      'caching_time' => 86400,
+      'value_type' => 'number',
+      'value_label' => 'ms',
+      'thresholds' => [
+        'type' => 'exceeds',
+        'warning' => 3000,
+        'critical' => 3200,
+      ],
+      'settings' => [
+        'main_metric' => 'percentile_90',
+        'lines' => 25,
+        'log_file' => drupal_get_path('module', 'monitoring') . '/tests/fixtures/example.php.access.log',
+      ],
+    ]);
+    $sensor->save();
+
+    $sensor_result = $this->runSensor('response_time_test');
+    $this->assertTrue($sensor_result->isOk());
+    $this->assertEquals('2935 ms, Average: 1010 ms, 90%: 2935 ms, 95%: 4626ms, start date: 2021-11-13T15:36:54Z', $sensor_result->getMessage());
+
+    // More lines than the length of the file.
+    $sensor->set('settings', [
+      'main_metric' => 'percentile_90',
+      'lines' => 2500,
+      'log_file' => 'modules/contrib/monitoring/tests/fixtures/example.php.access.log',
+    ]);
+    $sensor->save();
+    \Drupal::state()->delete('monitoring.response_time_test');
+    $sensor_result = $this->runSensor('response_time_test');
+    $this->assertTrue($sensor_result->isOk());
+    $this->assertEquals('2856 ms, Average: 975 ms, 90%: 2856 ms, 95%: 4540ms, start date: 2021-11-13T15:23:36Z', $sensor_result->getMessage());
+
+    // Change thresholds to get the warning status.
+    $sensor->set('thresholds', [
+      'type' => 'exceeds',
+      'warning' => '2800',
+      'critical' => 3000,
+    ]);
+    $sensor->save();
+    $sensor_result = $this->runSensor('response_time_test');
+    $this->assertTrue($sensor_result->isWarning());
+    $this->assertEquals('2856 ms, exceeds 2800, Average: 975 ms, 90%: 2856 ms, 95%: 4540ms, start date: 2021-11-13T15:23:36Z', $sensor_result->getMessage());
+
+    // Change thresholds to get the critical status.
+    $sensor->set('thresholds', [
+      'type' => 'exceeds',
+      'warning' => '2500',
+      'critical' => 2800,
+    ]);
+    $sensor->save();
+    $sensor_result = $this->runSensor('response_time_test');
+    $this->assertTrue($sensor_result->isCritical());
+    $this->assertEquals('2856 ms, exceeds 2800, Average: 975 ms, 90%: 2856 ms, 95%: 4540ms, start date: 2021-11-13T15:23:36Z', $sensor_result->getMessage());
+
+    // New metric.
+    $sensor->set('settings', [
+      'main_metric' => 'percentile_95',
+      'lines' => 25,
+      'log_file' => 'modules/contrib/monitoring/tests/fixtures/example.php.access.log',
+    ]);
+    $sensor->save();
+    $sensor_result = $this->runSensor('response_time_test');
+    $this->assertEquals('4626', $sensor_result->getValue());
+    $this->assertTrue($sensor_result->isCritical());
+    $this->assertEquals('4626 ms, exceeds 2800, Average: 1010 ms, 90%: 2935 ms, 95%: 4626ms, start date: 2021-11-13T15:36:54Z', $sensor_result->getMessage());
+
+    // New metric.
+    $sensor->set('settings', [
+      'main_metric' => 'average',
+      'lines' => 25,
+      'log_file' => 'modules/contrib/monitoring/tests/fixtures/example.php.access.log',
+    ]);
+    $sensor->save();
+    $sensor_result = $this->runSensor('response_time_test');
+    $this->assertEquals('1010', $sensor_result->getValue());
+    $this->assertTrue($sensor_result->isOk());
+    $this->assertEquals('1010 ms, Average: 1010 ms, 90%: 2935 ms, 95%: 4626ms, start date: 2021-11-13T15:36:54Z', $sensor_result->getMessage());
+
+    // Set invalid file.
+    $sensor->set('settings', [
+      'main_metric' => 'percentile_90',
+      'lines' => 25,
+      'log_file' => '/example.php.access.log',
+    ]);
+    $sensor->save();
+    $sensor_result = $this->runSensor('response_time_test');
+    $this->assertTrue($sensor_result->isCritical());
+    $this->assertEquals('Exception: Log file /example.php.access.log not found.', $sensor_result->getMessage());
+
+    // Empty file.
+    $sensor->set('settings', [
+      'main_metric' => 'percentile_90',
+      'lines' => 25,
+      'log_file' => 'modules/contrib/monitoring/tests/fixtures/empty.php.access.log',
+    ]);
+    $sensor->save();
+    $sensor_result = $this->runSensor('response_time_test');
+    $this->assertTrue($sensor_result->isWarning());
+    $this->assertEquals('Log file modules/contrib/monitoring/tests/fixtures/empty.php.access.log is empty.', $sensor_result->getMessage());
+
+  }
+
+}