diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml new file mode 100644 index 0000000..8f6a575 --- /dev/null +++ b/.github/workflows/ci.yml @@ -0,0 +1,121 @@ +name: CI + +on: + push: + branches: [master] + pull_request: + +jobs: + shell: + name: Shell + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v4 + + - name: Syntax check + run: bash -n scripts/drush-healthcheck.sh + + - name: ShellCheck + uses: ludeeus/action-shellcheck@master + with: + severity: warning + scandir: ./scripts + + php: + name: PHP ${{ matrix.php }} / Drupal ${{ matrix.drupal }} + runs-on: ubuntu-latest + strategy: + fail-fast: false + matrix: + include: + - drupal: '10.3' + php: '8.1' + - drupal: '11' + php: '8.3' + + services: + mysql: + image: mariadb:10.6 + env: + MYSQL_ALLOW_EMPTY_PASSWORD: 1 + MYSQL_DATABASE: drupal + ports: ['3306:3306'] + options: >- + --health-cmd="healthcheck.sh --connect --innodb_initialized" + --health-interval=10s --health-timeout=5s --health-retries=5 + + steps: + - name: Checkout module + uses: actions/checkout@v4 + with: + path: module + + - uses: shivammathur/setup-php@v2 + with: + php-version: ${{ matrix.php }} + extensions: gd, pdo_mysql, posix + coverage: none + + - name: Build a Drupal site around the module + run: | + composer create-project drupal/recommended-project:^${{ matrix.drupal }} drupal \ + --no-interaction --no-install + cd drupal + composer config minimum-stability dev + composer config --no-plugins allow-plugins true + composer config repositories.module path ../module + # -W because core-dev pulls dependency versions that conflict with + # the ones recommended-project pinned in its lock file. + # Drush is listed explicitly: a dependency's require-dev is not + # installed, so the module's own entry does not provide it here, and + # the site install step below needs it. + composer require --dev \ + drupal/core-dev:^${{ matrix.drupal }} \ + drush/drush:^13 \ + -W --no-interaction + composer require fivejars/logs_monitoring:@dev --no-interaction + + - name: Coding standards + working-directory: drupal + run: | + vendor/bin/phpcs --standard=Drupal,DrupalPractice \ + --extensions=php,module,install,inc,test \ + web/modules/contrib/logs_monitoring + + - name: Static analysis + working-directory: drupal + run: | + vendor/bin/phpstan analyse \ + --configuration=vendor/drupal/core-dev/phpstan-drupal-core.neon.dist \ + --level=1 \ + web/modules/contrib/logs_monitoring || \ + vendor/bin/phpstan analyse --level=1 web/modules/contrib/logs_monitoring + + # Functional tests reach their own test site by sending the DB prefix in + # the User-Agent, which core validates against the site's hash salt. With + # no settings.php there is no salt, validation fails, and every request + # falls through to the installer - which answers 200 to everything and + # makes every assertion fail in a way that looks like a module bug. + - name: Install Drupal + working-directory: drupal + run: | + vendor/bin/drush site:install standard \ + --db-url=mysql://root@127.0.0.1:3306/drupal \ + --account-pass=admin --no-interaction + chmod -R 0777 web/sites/default + mkdir -p web/sites/simpletest && chmod 0777 web/sites/simpletest + + - name: Tests + working-directory: drupal + env: + SIMPLETEST_DB: mysql://root@127.0.0.1:3306/drupal + SIMPLETEST_BASE_URL: http://127.0.0.1:8080 + BROWSERTEST_OUTPUT_DIRECTORY: /tmp/browser_output + SYMFONY_DEPRECATIONS_HELPER: weak + run: | + mkdir -p /tmp/browser_output + vendor/bin/drush runserver 127.0.0.1:8080 >/dev/null 2>&1 & + sleep 3 + vendor/bin/phpunit \ + --configuration web/core/phpunit.xml.dist \ + --group logs_monitoring diff --git a/README.md b/README.md index 4fe8a4c..7eed894 100644 --- a/README.md +++ b/README.md @@ -1,16 +1,445 @@ # Logs monitoring -Provides endpoint that indicate about errors in the log files. +Provides endpoints that indicate about errors in the log files, about cron that +stopped running and about Drush that stopped working from the CLI. + +Requires Drupal 10.3 or newer and PHP 8.1 or newer. The Drush heartbeat +additionally needs Drush 12.5 or newer, which is what discovers commands from +`src/Drush/Commands`. ## Configuration -In the form /admin/config/development/logs-monitoring-settings should be set: +In the form /admin/config/development/logs-monitoring-settings, reachable from +the *Settings* tab of /admin/reports/monitoring, should be set: 1) paths to logs 2) a count of rows in the end where a search will be performed -3) a list of the words that indicate errors. +3) a list of the words that indicate errors +4) a max age per log, in seconds +5) the cron max age, in seconds +6) the Drush heartbeat max age, in seconds. + +All three checks also appear on /admin/reports/status, so the same state is +visible to anyone already looking at the status report. + +> **After running database updates, export configuration.** The update hooks +> create the `rest.resource.logs_monitoring_cron` and +> `rest.resource.logs_monitoring_drush` config entities and grant the matching +> role permissions. On a site that keeps configuration in version control, the +> next `drush config:import` deletes anything not present in the sync directory +> — which silently removes the endpoints and leaves your monitor alerting with +> no visible cause. Run `drush config:export` and commit the two +> `rest.resource.*` files together with `user.role.anonymous` and +> `user.role.authenticated`. + +### The overview page + +/admin/reports/monitoring shows the live result of all three checks in one +table - exactly what an uptime monitor polling the endpoints would see at that +moment, including the per-log breakdown, any failing Ultimate Cron jobs, and the +CLI diagnostics from the last Drush heartbeat. It also lists each endpoint as an +absolute link, ready to paste into a monitor, and reports a route that has gone +missing rather than rendering a link that would 404. + +A *Settings* tab leads to the settings form and back again, so the two are +reachable from each other even though they live under different roots. + +Use it to answer "is the monitor right?" without waiting for a poll. If this page +and your alerts disagree, the monitor configuration is wrong rather than the +check. + +It requires *administer site configuration*, the same permission as the settings +form - so by default only user 1 and roles flagged as administrator can reach it, +and nothing is granted to anonymous. The endpoints themselves stay open to +anonymous, because a monitor cannot authenticate. + +The checks run in-process rather than over HTTP. A request to our own site would +have to guess a reachable base URL, would pass through whatever authentication +sits in front of the environment, and would appear in the very access logs this +module reads. ### Usage -The module provide REST endpoint /admin/reports/logs-monitoring where a list + +Every endpoint lives under /admin/reports/monitoring/: + +| Check | Path | +| --- | --- | +| Overview page | `/admin/reports/monitoring` | +| Logs | `/admin/reports/monitoring/logs` | +| Cron | `/admin/reports/monitoring/cron` | +| Drush | `/admin/reports/monitoring/drush` | + +The logs endpoint used to be at `/admin/reports/logs-monitoring`. That path still +works and returns the identical response, because it is already configured in +uptime monitors and a monitoring URL that starts answering 404 is the one kind of +breakage nobody notices — it looks like healthy silence. Only the new paths are +guaranteed going forward, so move your monitors when convenient. + +#### Logs +The module provide REST endpoint /admin/reports/monitoring/logs where a list of logs with their statuses will be provided. It can be used by Uptimerobot to detect errors. Returns HTTP status codes: -- 200 - no errors found -- 500 - some errors found +- 200 - every configured log is healthy +- 503 - at least one log is unhealthy + +A log is unhealthy when any of these is true: + +| `status` | Meaning | +| --- | --- | +| `NOK` | One of the configured error words was found. | +| `Not found.` | The configured path does not exist. | +| `Unreadable.` | The path exists but cannot be read — wrong owner, wrong mode. | +| `Stale.` | Nothing has been written for longer than the log's max age. | + +The last three matter as much as the first. A rotated, renamed or +permission-denied log cannot be searched at all, and a log nobody is writing to +produces no error text to find — both would otherwise report healthy. + +`Stale.` is the general form of the cron check below: give each log a max age and +the endpoint alerts when whatever writes to it stops. Every log has one — it +defaults to an hour if left empty. + +For a log that is only written when something goes wrong, silence *is* the +healthy state, so a normal max age would report it stale forever. Give those a +deliberately long value such as `31536000` (a year) to take them out of the +staleness check while keeping the error-word search. + +#### Cron +The REST endpoint /admin/reports/monitoring/cron reports how long ago cron last +completed. Point a second Uptimerobot monitor at it. +Returns HTTP status codes: +- 200 - cron completed within the configured max age +- 503 - cron has not completed within the configured max age, or never ran + +Example response: + +```json +{ + "check": "cron", + "status": "ok", + "last_run": 1753600000, + "age_seconds": 312, + "threshold": 3600 +} +``` + +`status` is one of `ok`, `stale` or `never`. When it is `never` there is no +`system.cron_last` timestamp yet and `age_seconds` is `null`. + +Core's `Cron::run()` calls `invokeCronHandlers()`, then `processQueues()`, and +only then `setCronLastTime()`, so a cron run that dies part way through — fatal +error, PHP timeout, OOM, killed worker — never advances the timestamp. The +endpoint therefore detects a cron that fails as well as one that was never +triggered. + +**What it does not detect:** a queue worker that throws on every item. Core +catches `\Exception` in `Cron::processQueue()`, logs it and leaves the item +queued, so cron still reaches `setCronLastTime()` and this check still reports +`ok`. A broken third-party sync is exactly this shape. Cover it by pointing a +log config at the Drupal error log, where those exceptions are recorded. + +##### With Ultimate Cron installed + +A single timestamp is a poor signal on an Ultimate Cron site. Every job is +scheduled independently and per-job failures are caught by design so one bad job +cannot stop the others — which means a broken job leaves `system.cron_last` +looking perfectly healthy. + +Enable the bundled **Logs monitoring: Ultimate Cron** submodule +(`logs_monitoring_ultimate_cron`) and this endpoint also inspects every enabled +job, reporting `degraded` with HTTP 503 when cron itself is firing but a job is +not: + +| `reason` | What happened | +| --- | --- | +| `failed` | The job's last scheduled run logged an error or worse. | +| `unfinished` | The run started and never completed — fatal, OOM, killed worker. Jobs currently holding their lock are skipped, since a running job looks identical until it finishes. | +| `behind` | The job is more than *Cron max age* past its own next scheduled time. | + +The response names the offending jobs, so the alert tells you where to look: + +```json +{ + "check": "cron", + "status": "degraded", + "last_run": 1753600000, + "age_seconds": 120, + "threshold": 3600, + "jobs_checked": true, + "failing_jobs": [ + { + "job": "node_cron", + "title": "Node cron", + "reason": "failed", + "detail": "Uncaught TypeError in node_cron()..." + } + ] +} +``` + +Each job's own schedule decides whether it is late — Ultimate Cron computes that +via its scheduler plugin, so a weekly job is not judged against a 15-minute one. +*Cron max age* is reused as the grace period, because Ultimate Cron's own +catch-up tolerance defaults to 0 and a job counts as behind the instant its +scheduled time passes, before the launcher has reached it. Alerting on that would +flap on every poll. + +Disabled jobs are ignored. Add job IDs to *Jobs to exclude* on the settings form +for jobs whose failures should not page anyone. + +Requires Ultimate Cron `8.x-2.0-beta1` or newer, which is the release supporting +Drupal 10.1+ and 11. Nothing is added on sites without the submodule — the extra +keys simply do not appear in the response. + +The integration is a submodule rather than a runtime check inside the main +module, so the Ultimate Cron dependency is declared rather than guessed at: the +code cannot be reached without it, and the main module contains no reference to +it at all. It plugs in through two hooks, documented in `logs_monitoring.api.php` +and usable by anything else that can tell a check is unhealthy: + +| Hook | Purpose | +| --- | --- | +| `hook_logs_monitoring_problems($check)` | Report reasons a check is unhealthy beyond its own staleness. Any problem returned makes the endpoint answer 503 `degraded`. | +| `hook_logs_monitoring_response_alter(&$data, $check)` | Add detail to the response body, so the alert names what broke. | + +#### Drush + +The REST endpoint /admin/reports/monitoring/drush reports how long ago Drush +last completed a health check from the CLI. Point a third Uptimerobot monitor +at it. + +Returns HTTP status codes: +- 200 - the heartbeat was recorded within the configured max age +- 503 - the heartbeat is older than the configured max age, or was never + recorded + +Example response: + +```json +{ + "check": "drush", + "status": "ok", + "last_run": 1753600000, + "age_seconds": 312, + "threshold": 3600 +} +``` + +`status` is one of `ok`, `stale` or `never`. When it is `never` no heartbeat has +been recorded yet and `age_seconds` is `null`. Users with the *administer site +configuration* permission also get a `meta` object holding the CLI PHP version +and SAPI, the Drush version, the hostname, the system user and how long the check +took - the values needed to work out why a heartbeat went stale. It is withheld +from everyone else so an anonymous uptime monitor is not handed the host's +internals. + +##### How it works + +A web request cannot test Drush. Shelling out from the web server would run +under the wrong PHP SAPI, the wrong user and the wrong environment, which is +exactly where CLI-only breakage hides. So the check is inverted: the CLI does +the work and the endpoint only reads the result. + +`drush logs-monitoring:heartbeat`, scheduled in the system crontab, bootstraps +Drupal, runs a real database query, runs an entity query and only then records a +timestamp in Drupal State. The write is last on purpose - any failure above it +leaves the previous timestamp in place, the endpoint goes stale and your monitor +alerts. Nothing has to push a failure anywhere, which is what makes this a dead +man's switch rather than a report that can itself go missing. + +Anything that stops scheduled Drush from completing is caught: a broken +`vendor/` directory, a CLI PHP upgrade that no longer matches the codebase, a +`settings.php` the cron user cannot read, database credentials that only work +over the web server's socket, a PHP memory limit that differs between SAPIs, or +a crontab entry that was removed during a deploy. + +Note what that last one implies: a stale heartbeat means *scheduled Drush +execution* is broken, which is not the same claim as "the Drush binary is +broken". Whoever gets paged should check the crontab first. A dead crontab will +also make the cron endpoint go stale, so expect both monitors to fire together. + +##### Setup + +1. Verify the command runs at all: + + ```bash + cd /var/www/example.com + vendor/bin/drush logs-monitoring:heartbeat + ``` + + On a multisite, add `--uri=example.com`. + +2. Schedule it as the user that owns the codebase - not root, or it will leave + root-owned files in the Drupal file system and caches. For a single site the + crontab line needs nothing but Drush: + + ```cron + */15 * * * * flock -n /run/lock/lm-hb.lock timeout 120 /var/www/example.com/vendor/bin/drush logs-monitoring:heartbeat -q + ``` + + `flock` stops overlapping runs piling up and `timeout` stops a hung database + wedging cron. For a multisite, or if you want one entry that loops over + several sites, use the bundled wrapper instead - see below. + +3. Set the *Drush heartbeat max age* on the settings form comfortably above the + crontab interval, so one missed run does not raise an alert. With the + 15-minute schedule above, 3600 seconds tolerates three consecutive failures + before alerting. + +4. Add the Uptimerobot monitor for /admin/reports/monitoring/drush. + +Until the first heartbeat is recorded the endpoint answers 503 `never`, and +/admin/reports/status says so - including a note when Drush 12.5 or newer is not +present in the codebase at all, which is the one case where the crontab entry +exits successfully while recording nothing. + +##### The wrapper script + +`scripts/drush-healthcheck.sh` adds a lock, a timeout, a loop over the sites of +a multisite, a `drush version` pre-flight that produces a readable error when +the binary itself is broken, and an optional outbound ping. It is optional; the +crontab line above covers a single site without it. + +```bash +cp scripts/drush-healthcheck.conf.example /etc/drush-healthcheck.conf +$EDITOR /etc/drush-healthcheck.conf +``` + +`DRUPAL_ROOT`, `DRUSH_BIN` and `DRUSH_HC_SITES` are required. The script exits 2 +without them rather than probing for a docroot: a wrong guess would report a +different site as healthy, which is worse than not running at all. + +It needs bash. Starting it as `sh drush-healthcheck.sh` bypasses the shebang, so +it re-execs itself under bash rather than letting dash report `Bad substitution` +where a health verdict should be. Relative paths for `--root` and `--drush` are +fine — the binary is resolved against your current directory before the script +changes into the Drupal root. + +```cron +*/15 * * * * /var/www/example.com/web/modules/contrib/logs_monitoring/scripts/drush-healthcheck.sh -q +``` + +`-q` keeps cron silent on success and still mails you the stderr of a failure. + +Run `scripts/drush-healthcheck.sh --help` for all options. Exit codes: 0 +healthy, 1 a check failed, 2 bad usage or configuration, 3 another instance is +running. + +##### Optional: external dead man's switch + +Setting `DRUSH_HC_PING_URL` makes the script curl a URL once every site has +passed, for use with Healthchecks.io, Cronitor or an Uptimerobot heartbeat +monitor. That takes Drupal out of the alert path entirely, so a broken web stack +cannot mask a Drush failure. It needs outbound network access from the server +and keeps the monitoring configuration outside the repository, so treat it as a +complement to the endpoint rather than a replacement. + +On a multisite the URL must contain `{site}`, which is replaced with the site +URI. A single shared URL cannot say which site it is reporting on, so a healthy +site would keep the switch green while another one is dead; the script exits 2 +rather than let that happen. + +## Configuring Uptimerobot + +Three monitors, one per endpoint. All three answer 200 when healthy and a +non-2xx when not, which is exactly what Uptimerobot's default HTTP monitor +alerts on — so there is nothing unusual to configure. + +### 1. Create the monitors + +For each of the three endpoints: + +- **Monitor Type**: `HTTP(s)` +- **Friendly Name**: `example.com — cron` (and `— drush`, `— logs`) +- **URL**: the full endpoint URL, for example + `https://example.com/admin/reports/monitoring/cron` +- **Monitoring Interval**: 5 minutes is fine. It must be shorter than the max + ages you configured, or an outage can start and end between two polls. + +| Monitor | URL | +| --- | --- | +| Logs | `https://example.com/admin/reports/monitoring/logs` | +| Cron | `https://example.com/admin/reports/monitoring/cron` | +| Drush | `https://example.com/admin/reports/monitoring/drush` | + +If you already have a monitor on the old `/admin/reports/logs-monitoring`, it +keeps working — repoint it at the new path when convenient. + +No `?_format=json` is needed. Each resource declares a single format, which makes +json the default for its route — a plain GET works. Appending it does no harm if +you prefer to be explicit. + +### 2. Leave these settings alone + +- **Keyword monitoring**: not needed, and do not use it. The status code is the + signal; matching on body text would break the moment a status string changes. +- **Authentication**: none. The endpoints are granted to anonymous on install + precisely so a monitor can reach them without credentials. +- **Alert When Down**: default. Any non-2xx counts, so 500, 503 and a 403 from a + lost permission all page you. + +### 3. Set the thresholds to match the interval + +On /admin/config/development/logs-monitoring-settings, each max age should be +comfortably larger than how often the thing it watches is supposed to run — at +least three times the interval, so one missed run does not page anyone: + +| Setting | Rule of thumb | +| --- | --- | +| Cron max age | ≥ 3× your cron interval | +| Drush heartbeat max age | ≥ 3× the crontab interval of the heartbeat | +| Per-log max age | ≥ 3× how often that log's writer runs, or a year for an error-only log | + +### 4. Confirm each monitor actually reacts + +Do not skip this. A monitor that was never proven to go red is not monitoring +anything. Break each check, watch Uptimerobot report Down, then restore it: + +```bash +# Cron +drush sset system.cron_last 1 # expect Down within one interval +drush cron # expect Up + +# Drush heartbeat +drush state:delete logs_monitoring.drush_last +drush logs-monitoring:heartbeat + +# Logs +echo "Uncaught PHP Exception: test" >> /var/log/php_error.log +``` + +You can check the code yourself without waiting for a poll: + +```bash +curl -s -o /dev/null -w '%{http_code}\n' https://example.com/admin/reports/monitoring/cron +``` + +### Notes + +- **Three monitors per site** adds up against the free plan's 50-monitor cap. If + that bites, drop the logs monitor last — it is the one whose failures usually + also show up in other tooling. +- **A CDN or reverse proxy in front of Drupal** must not cache these. The + responses send `Cache-Control: no-store`, but verify it end to end: a cached + 200 would keep reassuring you after the site broke. +- **`automated_cron`** instead of a real crontab means cron only runs when + someone visits the site. On a low-traffic site the cron monitor will go red + during quiet periods with nothing actually broken — either raise the max age + or move to a real crontab entry. + +##### Inspecting and testing + +```bash +# What was last recorded. +drush state:get logs_monitoring.drush_last --format=yaml + +# Simulate a dead Drush: delete the heartbeat, endpoint answers 503 "never". +drush state:delete logs_monitoring.drush_last + +# Simulate a stale heartbeat: backdate it beyond the threshold. +drush state:set logs_monitoring.drush_last 1 --input-format=integer + +# Run the checks without touching state, e.g. against a read-only replica. +drush logs-monitoring:heartbeat --no-state +``` + +A bare integer is accepted as a heartbeat, which is why the `state:set` line +above works for testing. diff --git a/composer.json b/composer.json index b339d4f..4d23adf 100644 --- a/composer.json +++ b/composer.json @@ -3,5 +3,11 @@ "description": "Logs monitoring", "type": "drupal-module", "license": "GPL-2.0+", - "minimum-stability": "dev" + "minimum-stability": "dev", + "require": { + "php": ">=8.1" + }, + "require-dev": { + "drush/drush": "^12.5 || ^13" + } } diff --git a/config/install/logs_monitoring.settings.yml b/config/install/logs_monitoring.settings.yml index 5f0383b..8ad0209 100644 --- a/config/install/logs_monitoring.settings.yml +++ b/config/install/logs_monitoring.settings.yml @@ -1 +1,6 @@ log_configs: [] +cron: + max_age: 3600 + excluded_jobs: [] +drush: + max_age: 3600 diff --git a/config/install/rest.resource.logs_monitoring_cron.yml b/config/install/rest.resource.logs_monitoring_cron.yml new file mode 100644 index 0000000..54d0247 --- /dev/null +++ b/config/install/rest.resource.logs_monitoring_cron.yml @@ -0,0 +1,17 @@ +langcode: en +status: true +dependencies: + module: + - serialization + - user + - logs_monitoring +id: logs_monitoring_cron +plugin_id: logs_monitoring_cron +granularity: resource +configuration: + methods: + - GET + formats: + - json + authentication: + - cookie diff --git a/config/install/rest.resource.logs_monitoring_drush.yml b/config/install/rest.resource.logs_monitoring_drush.yml new file mode 100644 index 0000000..dda21cb --- /dev/null +++ b/config/install/rest.resource.logs_monitoring_drush.yml @@ -0,0 +1,17 @@ +langcode: en +status: true +dependencies: + module: + - serialization + - user + - logs_monitoring +id: logs_monitoring_drush +plugin_id: logs_monitoring_drush +granularity: resource +configuration: + methods: + - GET + formats: + - json + authentication: + - cookie diff --git a/config/schema/logs_monitoring.schema.yml b/config/schema/logs_monitoring.schema.yml new file mode 100644 index 0000000..db649b8 --- /dev/null +++ b/config/schema/logs_monitoring.schema.yml @@ -0,0 +1,46 @@ +logs_monitoring.settings: + type: config_object + label: 'Logs monitoring settings' + mapping: + log_configs: + type: sequence + label: 'Log configs' + sequence: + type: mapping + label: 'Log config' + mapping: + path_to_logs: + type: string + label: 'Path to the log' + search_words: + type: text + label: 'Error words to search' + exclude_words: + type: text + label: 'Words to exclude' + lines_count: + type: integer + label: 'Count of lines to read' + max_age: + type: integer + label: 'Max age in seconds' + cron: + type: mapping + label: 'Cron monitoring' + mapping: + max_age: + type: integer + label: 'Cron max age in seconds' + excluded_jobs: + type: sequence + label: 'Ultimate Cron job IDs excluded from monitoring' + sequence: + type: string + label: 'Job ID' + drush: + type: mapping + label: 'Drush monitoring' + mapping: + max_age: + type: integer + label: 'Drush heartbeat max age in seconds' diff --git a/logs_monitoring.api.php b/logs_monitoring.api.php new file mode 100644 index 0000000..3a32c88 --- /dev/null +++ b/logs_monitoring.api.php @@ -0,0 +1,57 @@ + 'failed', + 'detail' => 'The nightly import logged an error on its last run.', + ], + ]; +} + +/** + * Alters the body of a monitoring check's response. + * + * Use this to add detail an operator needs in order to act - naming what broke, + * rather than only that something did. Do not remove the keys the check itself + * sets: an uptime monitor reads the status code, but a human reads this. + * + * @param array $data + * The response data, by reference. + * @param string $check + * The check being evaluated: "cron" or "drush". + * + * @see \Drupal\logs_monitoring\Plugin\rest\resource\StalenessResourceBase::get() + */ +function hook_logs_monitoring_response_alter(array &$data, string $check): void { + if ($check === 'cron') { + $data['jobs_checked'] = TRUE; + } +} diff --git a/logs_monitoring.info.yml b/logs_monitoring.info.yml index 1d1fd9b..36936c9 100644 --- a/logs_monitoring.info.yml +++ b/logs_monitoring.info.yml @@ -1,8 +1,7 @@ name: Logs monitoring type: module description: Provides functionality for logs monitoring. -core: 8.x -core_version_requirement: ^8 || ^9 || ^10 +core_version_requirement: ^10.3 || ^11 package: Development dependencies: - drupal:rest diff --git a/logs_monitoring.install b/logs_monitoring.install index c0e275d..26fac24 100644 --- a/logs_monitoring.install +++ b/logs_monitoring.install @@ -5,6 +5,8 @@ * Contains install and update routines. */ +use Drupal\Component\Serialization\Yaml; +use Drupal\logs_monitoring\LogsMonitoringInterface; use Drupal\user\Entity\Role; use Drupal\user\RoleInterface; @@ -14,18 +16,287 @@ use Drupal\user\RoleInterface; function logs_monitoring_install($is_syncing) { // Add permissions to anonymous and authenticated roles. if (!$is_syncing) { - $permissions = [ + _logs_monitoring_grant_permissions([ 'restful get logs_monitoring', - ]; - $roles = Role::loadMultiple([ - RoleInterface::ANONYMOUS_ID, - RoleInterface::AUTHENTICATED_ID + 'restful get logs_monitoring_cron', + 'restful get logs_monitoring_drush', ]); - foreach ($roles as $role) { - foreach ($permissions as $permission) { - $role->grantPermission($permission); - } - $role->save(); + } +} + +/** + * Implements hook_requirements(). + * + * The endpoints only answer when something asks them. These rows make the same + * state visible to whoever is already looking at the status report, and they + * are the only place a never-recorded Drush heartbeat can be explained rather + * than just reported - the endpoint cannot tell "not scheduled yet" apart from + * "scheduled but broken", and this can. + * + * Drupal 11.3 emits a deprecation for a procedural implementation without a + * #[LegacyRequirementsHook] attribute. Do not add it here: that attribute + * *suppresses* the legacy hook on 11.3+, and is only correct for a module that + * also ships an OOP #[Hook('runtime_requirements')] replacement. Adding it + * without one silently removes every row below from the status report. Accept + * the deprecation until the floor becomes ^11.3 and this can move to a + * #[Hook('runtime_requirements')] class. + */ +function logs_monitoring_requirements($phase) { + if ($phase !== 'runtime') { + return []; + } + + $requirements = []; + $settings = \Drupal::config(LogsMonitoringInterface::CONFIG_NAME); + $now = \Drupal::time()->getRequestTime(); + + // Cron. + $cron_threshold = (int) $settings->get('cron.max_age') + ?: LogsMonitoringInterface::DEFAULT_MAX_AGE; + $cron_last = (int) \Drupal::state()->get(LogsMonitoringInterface::STATE_CRON_LAST, 0); + $requirements['logs_monitoring_cron'] = [ + 'title' => t('Logs monitoring: cron'), + ] + _logs_monitoring_staleness_requirement( + $cron_last, + $cron_threshold, + $now, + t('Cron has never completed on this site.') + ); + + // Drush heartbeat. + $drush_threshold = (int) $settings->get('drush.max_age') + ?: LogsMonitoringInterface::DEFAULT_MAX_AGE; + $heartbeat = \Drupal::service('logs_monitoring.heartbeat')->read(); + $never_description = t('No heartbeat has been recorded yet. Schedule "drush logs-monitoring:heartbeat" in the system crontab - see the module README.'); + + // A missing AutowireTrait means Drush either is not installed in this + // codebase or predates the command discovery this module relies on, in which + // case the crontab entry exits 0 without ever recording anything. Only + // mention it when the heartbeat is actually missing: a site running Drush + // from outside the codebase has no such class here and is working fine. + if (!$heartbeat && !class_exists('Drush\Commands\AutowireTrait')) { + $never_description = t('No heartbeat has been recorded yet, and Drush 12.5 or newer was not found in this codebase. The logs-monitoring:heartbeat command cannot be discovered by an older Drush, so a crontab entry calling it would exit successfully without recording anything.'); + } + + $requirements['logs_monitoring_drush'] = [ + 'title' => t('Logs monitoring: Drush heartbeat'), + ] + _logs_monitoring_staleness_requirement( + $heartbeat['ts'] ?? 0, + $drush_threshold, + $now, + $never_description + ); + + // Log files. + $formatter = \Drupal::service('date.formatter'); + $problems = []; + foreach ($settings->get('log_configs') ?? [] as $log_config) { + $path = trim($log_config['path_to_logs'] ?? ''); + if ($path === '') { + continue; + } + + if (!file_exists($path)) { + $problems[] = t('@path: not found.', ['@path' => $path]); + continue; + } + if (!is_readable($path)) { + $problems[] = t('@path: not readable by the web server user.', ['@path' => $path]); + continue; + } + + $max_age = (int) ($log_config['max_age'] ?? 0) + ?: LogsMonitoringInterface::DEFAULT_MAX_AGE; + $modified = filemtime($path); + if ($modified !== FALSE && ($now - $modified) > $max_age) { + $problems[] = t('@path: nothing written for @age (max @max).', [ + '@path' => $path, + '@age' => $formatter->formatInterval($now - $modified), + '@max' => $formatter->formatInterval($max_age), + ]); + } + } + + if ($problems) { + $requirements['logs_monitoring_logs'] = [ + 'title' => t('Logs monitoring: log files'), + 'value' => t('@count of the configured logs need attention', ['@count' => count($problems)]), + 'description' => [ + '#theme' => 'item_list', + '#items' => $problems, + ], + 'severity' => _logs_monitoring_severity('error'), + ]; + } + else { + $requirements['logs_monitoring_logs'] = [ + 'title' => t('Logs monitoring: log files'), + 'value' => t('All configured logs are readable and current'), + 'severity' => _logs_monitoring_severity('ok'), + ]; + } + + return $requirements; +} + +/** + * Returns a requirement severity in the form this Drupal version expects. + * + * Drupal 11.3 replaced the REQUIREMENT_* constants with a RequirementSeverity + * enum and 11.4 removed the constants outright, so referencing them fatals with + * "Undefined constant" and takes the whole status report down. Integers are + * still accepted there but raise a deprecation, and the enum does not exist on + * Drupal 10.3, which this module still supports - hence resolving at runtime. + * + * @param string $level + * One of "ok", "warning" or "error". + * + * @return \Drupal\Core\Extension\Requirement\RequirementSeverity|int + * The enum case where available, otherwise the legacy integer. + */ +function _logs_monitoring_severity(string $level) { + // The enum is int-backed with exactly these values, which are also what the + // REQUIREMENT_* constants were. + $legacy = [ + 'ok' => 0, + 'warning' => 1, + 'error' => 2, + ][$level]; + + $enum = 'Drupal\Core\Extension\Requirement\RequirementSeverity'; + + return enum_exists($enum) ? $enum::from($legacy) : $legacy; +} + +/** + * Builds the value/description/severity of a staleness requirement row. + * + * @param int $last + * When the check last completed, or 0 if it never has. + * @param int $threshold + * The staleness threshold, in seconds. + * @param int $now + * The current request time. + * @param \Drupal\Core\StringTranslation\TranslatableMarkup|string $never_description + * Description to use when the check has never completed. + * + * @return array + * Partial requirement definition. + */ +function _logs_monitoring_staleness_requirement(int $last, int $threshold, int $now, $never_description): array { + /** @var \Drupal\Core\Datetime\DateFormatterInterface $formatter */ + $formatter = \Drupal::service('date.formatter'); + + if ($last <= 0) { + return [ + 'value' => t('Never'), + 'description' => $never_description, + 'severity' => _logs_monitoring_severity('warning'), + ]; + } + + $age = $now - $last; + $value = t('@ago ago', ['@ago' => $formatter->formatInterval($age)]); + + if ($age >= $threshold) { + return [ + 'value' => $value, + 'description' => t('Older than the configured maximum of @max. The monitoring endpoint is answering 503.', [ + '@max' => $formatter->formatInterval($threshold), + ]), + 'severity' => _logs_monitoring_severity('error'), + ]; + } + + return [ + 'value' => $value, + 'severity' => _logs_monitoring_severity('ok'), + ]; +} + +/** + * Grants permissions to the anonymous and authenticated roles. + * + * @param array $permissions + * The permission names to grant. + */ +function _logs_monitoring_grant_permissions(array $permissions) { + $roles = Role::loadMultiple([ + RoleInterface::ANONYMOUS_ID, + RoleInterface::AUTHENTICATED_ID, + ]); + foreach ($roles as $role) { + foreach ($permissions as $permission) { + $role->grantPermission($permission); } + $role->save(); + } +} + +/** + * Creates a REST resource config entity from the module's install config. + * + * @param string $id + * The rest_resource_config entity ID, which is also the plugin ID. + */ +function _logs_monitoring_install_rest_resource(string $id) { + // The "restful get " permission is derived from the REST resource config + // entity, so both the plugin definition and the entity have to exist before + // the permission is granted - Role::calculateDependencies() silently strips + // permissions it cannot resolve. + \Drupal::service('plugin.manager.rest')->clearCachedDefinitions(); + + $storage = \Drupal::entityTypeManager()->getStorage('rest_resource_config'); + if (!$storage->load($id)) { + $module_path = \Drupal::service('extension.list.module')->getPath('logs_monitoring'); + $file = DRUPAL_ROOT . '/' . $module_path . '/config/install/rest.resource.' . $id . '.yml'; + $storage->create(Yaml::decode(file_get_contents($file)))->save(); + } + + _logs_monitoring_grant_permissions(['restful get ' . $id]); + + // Make sure the route of the new endpoint becomes available. + \Drupal::service('router.builder')->setRebuildNeeded(); +} + +/** + * Adds the cron monitoring endpoint and its staleness threshold. + */ +function logs_monitoring_update_10001() { + _logs_monitoring_install_rest_resource('logs_monitoring_cron'); + + $config = \Drupal::configFactory()->getEditable(LogsMonitoringInterface::CONFIG_NAME); + if (!$config->get('cron.max_age')) { + $config->set('cron.max_age', LogsMonitoringInterface::DEFAULT_MAX_AGE)->save(); } + + return (string) t('Run "drush config:export" and commit the new rest.resource.logs_monitoring_cron config and the updated user role permissions, otherwise the next configuration import will delete the endpoint.'); +} + +/** + * Adds the Drush monitoring endpoint and its staleness threshold. + */ +function logs_monitoring_update_10002() { + _logs_monitoring_install_rest_resource('logs_monitoring_drush'); + + $config = \Drupal::configFactory()->getEditable(LogsMonitoringInterface::CONFIG_NAME); + if (!$config->get('drush.max_age')) { + $config->set('drush.max_age', LogsMonitoringInterface::DEFAULT_MAX_AGE)->save(); + } + + // The endpoint stays at 503 until the heartbeat is recorded for the first + // time, which cannot happen until the crontab entry exists. + return (string) t('Schedule "drush logs-monitoring:heartbeat" in the system crontab, otherwise /admin/reports/monitoring/drush will keep reporting "never". Then run "drush config:export" and commit the new rest.resource.logs_monitoring_drush config and the updated user role permissions, otherwise the next configuration import will delete the endpoint. See the module README.'); +} + +/** + * Moves the endpoints under /admin/reports/monitoring/. + */ +function logs_monitoring_update_10003() { + // The paths come from the resource plugin annotations, so the definitions and + // the routes both have to be rebuilt for the new ones to resolve. + \Drupal::service('plugin.manager.rest')->clearCachedDefinitions(); + \Drupal::service('router.builder')->setRebuildNeeded(); + + return (string) t('The monitoring endpoints are now /admin/reports/monitoring/logs, /admin/reports/monitoring/cron and /admin/reports/monitoring/drush. The previous logs path /admin/reports/logs-monitoring still works and returns the same response, so existing uptime monitors keep functioning - but update them, since only the new paths are guaranteed going forward.'); } diff --git a/logs_monitoring.links.menu.yml b/logs_monitoring.links.menu.yml index 3ba3f87..cafe82d 100644 --- a/logs_monitoring.links.menu.yml +++ b/logs_monitoring.links.menu.yml @@ -1,5 +1,11 @@ logs_monitoring.settings: - title: 'Logs monitoring' + title: 'Monitoring settings' route_name: logs_monitoring.settings description: 'Settings form for logs monitoring' parent: system.admin_config_development + +logs_monitoring.overview: + title: 'Monitoring' + route_name: logs_monitoring.overview + description: 'What the uptime monitors currently see for the logs, cron and Drush checks' + parent: system.admin_reports diff --git a/logs_monitoring.links.task.yml b/logs_monitoring.links.task.yml new file mode 100644 index 0000000..cc8c50c --- /dev/null +++ b/logs_monitoring.links.task.yml @@ -0,0 +1,13 @@ +logs_monitoring.overview: + title: 'Monitoring' + route_name: logs_monitoring.overview + base_route: logs_monitoring.overview + +# The settings form keeps its place under Configuration - settings do not belong +# under Reports - but shares the overview's base route so the same two tabs +# render on both pages, and each is reachable from the other. +logs_monitoring.settings: + title: 'Settings' + route_name: logs_monitoring.settings + base_route: logs_monitoring.overview + weight: 10 diff --git a/logs_monitoring.routing.yml b/logs_monitoring.routing.yml index 9e6f986..e83e09e 100644 --- a/logs_monitoring.routing.yml +++ b/logs_monitoring.routing.yml @@ -1,7 +1,31 @@ +logs_monitoring.overview: + path: '/admin/reports/monitoring' + defaults: + _title: 'Monitoring' + _controller: '\Drupal\logs_monitoring\Controller\MonitoringController::overview' + requirements: + _permission: 'administer site configuration' + options: + no_cache: TRUE + logs_monitoring.settings: path: '/admin/config/development/logs-monitoring-settings' defaults: - _title: 'Logs monitoring' + _title: 'Monitoring settings' _form: '\Drupal\logs_monitoring\Form\LogsMonitoringSettingsForm' requirements: _permission: 'administer site configuration' + +# Superseded path, kept because it is already configured in uptime monitors. +# The canonical path is /admin/reports/monitoring/logs, served by the REST +# resource. Guarded by the same permission, which the REST resource config +# entity provides, so access cannot drift between the two paths. +logs_monitoring.logs_legacy: + path: '/admin/reports/logs-monitoring' + defaults: + _title: 'Logs monitoring' + _controller: '\Drupal\logs_monitoring\Controller\MonitoringController::logs' + requirements: + _permission: 'restful get logs_monitoring' + options: + no_cache: TRUE diff --git a/logs_monitoring.services.yml b/logs_monitoring.services.yml new file mode 100644 index 0000000..9d21f48 --- /dev/null +++ b/logs_monitoring.services.yml @@ -0,0 +1,8 @@ +services: + # Registered under its class name so it can be autowired, which is how Drush + # command classes resolve their constructor arguments. + Drupal\logs_monitoring\Heartbeat: + arguments: ['@state', '@datetime.time'] + logs_monitoring.heartbeat: + alias: Drupal\logs_monitoring\Heartbeat + public: true diff --git a/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.info.yml b/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.info.yml new file mode 100644 index 0000000..482b612 --- /dev/null +++ b/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.info.yml @@ -0,0 +1,8 @@ +name: 'Logs monitoring: Ultimate Cron' +type: module +description: 'Reports Ultimate Cron jobs that failed, crashed or fell behind schedule through the cron monitoring check.' +core_version_requirement: ^10.3 || ^11 +package: Development +dependencies: + - logs_monitoring:logs_monitoring + - ultimate_cron:ultimate_cron diff --git a/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.install b/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.install new file mode 100644 index 0000000..fbbccf7 --- /dev/null +++ b/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.install @@ -0,0 +1,58 @@ +loadInclude('logs_monitoring', 'install'); + + $problems = \Drupal::service('logs_monitoring_ultimate_cron.inspector')->findProblems(); + + if (!$problems) { + return [ + 'logs_monitoring_cron_jobs' => [ + 'title' => t('Logs monitoring: cron jobs'), + 'value' => t('All enabled jobs ran successfully and on schedule'), + 'severity' => _logs_monitoring_severity('ok'), + ], + ]; + } + + $items = []; + foreach ($problems as $problem) { + $items[] = t('@title (@job) - @reason: @detail', [ + '@title' => $problem['title'], + '@job' => $problem['job'], + '@reason' => $problem['reason'], + '@detail' => $problem['detail'], + ]); + } + + return [ + 'logs_monitoring_cron_jobs' => [ + 'title' => t('Logs monitoring: cron jobs'), + 'value' => t('@count job(s) need attention', ['@count' => count($problems)]), + 'description' => [ + '#theme' => 'item_list', + '#items' => $items, + ], + 'severity' => _logs_monitoring_severity('error'), + ], + ]; +} diff --git a/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.module b/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.module new file mode 100644 index 0000000..9f26ec7 --- /dev/null +++ b/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.module @@ -0,0 +1,82 @@ +findProblems(); +} + +/** + * Implements hook_logs_monitoring_response_alter(). + */ +function logs_monitoring_ultimate_cron_logs_monitoring_response_alter(array &$data, string $check): void { + if ($check !== 'cron') { + return; + } + + // Naming the jobs is the difference between an alert that says "cron is + // unhealthy" and one that says which job to go and look at. + $data['jobs_checked'] = TRUE; + $data['failing_jobs'] = \Drupal::service('logs_monitoring_ultimate_cron.inspector')->findProblems(); +} + +/** + * Implements hook_form_FORM_ID_alter() for logs_monitoring_settings. + */ +function logs_monitoring_ultimate_cron_form_logs_monitoring_settings_alter(array &$form, FormStateInterface $form_state): void { + $excluded = \Drupal::config(LogsMonitoringInterface::CONFIG_NAME)->get('cron.excluded_jobs') ?? []; + + $form['cron']['#description'] = t('Ultimate Cron runs each job independently and catches per-job failures, so one broken job leaves the cron timestamp looking healthy. This endpoint therefore also inspects every enabled job and reports degraded when one has failed, crashed part way through, or fallen more than the max age behind its own schedule.'); + $form['cron']['excluded_jobs'] = [ + '#type' => 'textarea', + '#title' => t('Jobs to exclude'), + '#description' => t('One Ultimate Cron job ID per line. Use for jobs whose failures should not page anyone. Disabled jobs are already ignored.'), + '#default_value' => implode(PHP_EOL, $excluded), + '#rows' => 4, + ]; + + $form['actions']['submit']['#submit'][] = 'logs_monitoring_ultimate_cron_settings_submit'; +} + +/** + * Saves the excluded job list. + * + * The parent form writes only the keys it owns, so this can add its own without + * the two fighting over the "cron" group. + * + * @param array $form + * The form. + * @param \Drupal\Core\Form\FormStateInterface $form_state + * The form state. + */ +function logs_monitoring_ultimate_cron_settings_submit(array &$form, FormStateInterface $form_state): void { + $raw = (string) $form_state->getValue(['cron', 'excluded_jobs']); + $jobs = []; + + if (trim($raw) !== '') { + foreach (preg_split('/\R/', $raw) as $line) { + $line = trim($line); + if ($line !== '') { + $jobs[] = $line; + } + } + } + + \Drupal::configFactory() + ->getEditable(LogsMonitoringInterface::CONFIG_NAME) + ->set('cron.excluded_jobs', $jobs) + ->save(); +} diff --git a/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.services.yml b/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.services.yml new file mode 100644 index 0000000..b484de0 --- /dev/null +++ b/modules/logs_monitoring_ultimate_cron/logs_monitoring_ultimate_cron.services.yml @@ -0,0 +1,8 @@ +services: + Drupal\logs_monitoring_ultimate_cron\CronJobsInspector: + arguments: + - '@entity_type.manager' + - '@config.factory' + logs_monitoring_ultimate_cron.inspector: + alias: Drupal\logs_monitoring_ultimate_cron\CronJobsInspector + public: true diff --git a/modules/logs_monitoring_ultimate_cron/src/CronJobsInspector.php b/modules/logs_monitoring_ultimate_cron/src/CronJobsInspector.php new file mode 100644 index 0000000..79b13f6 --- /dev/null +++ b/modules/logs_monitoring_ultimate_cron/src/CronJobsInspector.php @@ -0,0 +1,284 @@ +entityTypeManager = $entity_type_manager; + $this->configFactory = $config_factory; + } + + /** + * Returns the jobs that need attention. + * + * @return array + * A list of problems, each with "job", "title", "reason" and "detail" keys. + * Empty when every enabled job is healthy. + */ + public function findProblems(): array { + $settings = $this->configFactory->get(LogsMonitoringInterface::CONFIG_NAME); + + // The same threshold the whole-run check uses. Ultimate Cron's own catch-up + // tolerance defaults to 0, so a job counts as behind the moment its + // scheduled time passes and before the launcher reaches it - reporting that + // immediately would flap on every poll. + $grace = (int) $settings->get('cron.max_age') ?: LogsMonitoringInterface::DEFAULT_MAX_AGE; + $excluded = $settings->get('cron.excluded_jobs') ?? []; + + $jobs = []; + foreach ($this->loadJobs() as $id => $job) { + // Disabled jobs are not expected to run, and an excluded job is one the + // site has decided not to gate alerting on. + if (!$job->status() || in_array($id, $excluded, TRUE)) { + continue; + } + $jobs[$id] = $job; + } + + if (!$jobs) { + return []; + } + + $log_entries = $this->loadLogEntries($jobs); + + $problems = []; + foreach ($jobs as $id => $job) { + $problem = $this->inspectJob($job, $log_entries[$id] ?? NULL, $grace); + if ($problem) { + $problems[] = ['job' => $id, 'title' => (string) $job->getTitle()] + $problem; + } + } + + return $problems; + } + + /** + * Inspects one job. + * + * @param object $job + * The Ultimate Cron job. + * @param object|null $log_entry + * Its latest scheduled log entry, if one could be loaded. + * @param int $grace + * Seconds a job may be behind schedule before it is reported. + * + * @return array + * A partial problem with "reason" and "detail" keys, or an empty array when + * the job is healthy. + */ + protected function inspectJob($job, $log_entry, int $grace): array { + // A job whose last run logged an error is the case that matters most: it + // ran, it failed, and Ultimate Cron swallowed the failure by design so the + // rest of cron could continue. + $severity = $log_entry->severity ?? -1; + if ($severity >= 0 && $severity <= RfcLogLevel::ERROR) { + return [ + 'reason' => 'failed', + 'detail' => $this->truncate((string) ($log_entry->message ?: $log_entry->init_message)), + ]; + } + + // A start time with no end time means the run began and never finished - a + // fatal, an OOM or a killed worker. Skip a job that is legitimately running + // right now, which looks identical until it finishes. + $started = (float) ($log_entry->start_time ?? 0); + $ended = (float) ($log_entry->end_time ?? 0); + if ($started > 0 && $ended <= 0 && !$this->isRunning($job)) { + return [ + 'reason' => 'unfinished', + 'detail' => 'Last run started but never completed.', + ]; + } + + // Finally, a job that should have run by now and has not. + $behind = $this->behindSeconds($job); + if ($behind !== NULL && $behind > $grace) { + return [ + 'reason' => 'behind', + 'detail' => sprintf('Behind schedule by %d seconds.', $behind), + ]; + } + + return []; + } + + /** + * Loads all job entities. + * + * @return array + * Job entities keyed by ID, or an empty array if they cannot be loaded. + */ + protected function loadJobs(): array { + try { + return $this->entityTypeManager + ->getStorage(self::JOB_ENTITY_TYPE) + ->loadMultiple(); + } + catch (\Throwable $e) { + return []; + } + } + + /** + * Loads the latest scheduled log entry for each job. + * + * Grouped by logger so each one resolves its jobs in a single query - the + * database logger does that on MySQL - because this endpoint is polled + * continuously. + * + * Deliberately not CronJob::loadLatestLogEntries(). That static reads + * "$job->getPlugin('logger')->name", a property the Drupal 8+ logger plugins + * do not have, so it raises "Undefined property" and groups every job under + * an empty key. Note that an undefined property is a PHP warning, not a + * \Throwable, so calling it cannot be made safe with a try/catch: the warning + * reaches the site's error log and the caller still gets a wrong result. + * + * @param array $jobs + * Job entities keyed by ID. + * + * @return array + * Log entries keyed by job ID. A job whose entry cannot be loaded maps to + * NULL rather than being dropped, so the caller still sees it. + */ + protected function loadLogEntries(array $jobs): array { + if (!$jobs) { + return []; + } + + // Jobs can use different loggers, which is the grouping the broken static + // was there to do. + $by_logger = []; + foreach ($jobs as $id => $job) { + $by_logger[$job->getLoggerId()][$id] = $job; + } + + $entries = []; + foreach ($by_logger as $group) { + try { + $logger = reset($group)->getPlugin('logger'); + $entries += $logger->loadLatestLogEntries($group, [ULTIMATE_CRON_LOG_TYPE_NORMAL]); + } + catch (\Throwable $e) { + // Fall back to one query per job rather than losing the whole group. + foreach ($group as $id => $job) { + try { + $entries[$id] = $job->loadLatestLogEntry(); + } + catch (\Throwable $e) { + $entries[$id] = NULL; + } + } + } + } + + return $entries; + } + + /** + * Returns how many seconds a job is behind its own schedule. + * + * @param object $job + * The Ultimate Cron job. + * + * @return int|null + * Seconds behind, or NULL when the job is on schedule or cannot be judged. + */ + protected function behindSeconds($job): ?int { + try { + $behind = $job->isBehindSchedule(); + } + catch (\Throwable $e) { + return NULL; + } + + // Ultimate Cron returns FALSE when the job is not behind, and the number of + // seconds when it is. + return $behind === FALSE ? NULL : (int) $behind; + } + + /** + * Whether the job is executing right now. + * + * @param object $job + * The Ultimate Cron job. + * + * @return bool + * TRUE when the job holds its lock. + */ + protected function isRunning($job): bool { + try { + return (bool) $job->isLocked(); + } + catch (\Throwable $e) { + return FALSE; + } + } + + /** + * Shortens a log message for inclusion in a monitoring response. + * + * @param string $message + * The message. + * + * @return string + * A single-line, length-capped message. + */ + protected function truncate(string $message): string { + $message = trim(preg_replace('/\s+/', ' ', strip_tags($message))); + + if ($message === '') { + return 'Last run logged an error with no message.'; + } + + return mb_strlen($message) > 200 ? mb_substr($message, 0, 197) . '...' : $message; + } + +} diff --git a/modules/logs_monitoring_ultimate_cron/tests/src/Kernel/CronJobsInspectorTest.php b/modules/logs_monitoring_ultimate_cron/tests/src/Kernel/CronJobsInspectorTest.php new file mode 100644 index 0000000..0bd814e --- /dev/null +++ b/modules/logs_monitoring_ultimate_cron/tests/src/Kernel/CronJobsInspectorTest.php @@ -0,0 +1,209 @@ +installConfig(['logs_monitoring', 'ultimate_cron']); + $this->installSchema('ultimate_cron', ['ultimate_cron_log']); + $this->inspector = $this->container->get('logs_monitoring_ultimate_cron.inspector'); + } + + /** + * Creates a cron job. + * + * @param string $id + * The job ID. + * @param bool $status + * Whether the job is enabled. + * + * @return \Drupal\ultimate_cron\Entity\CronJob + * The saved job. + */ + protected function createJob(string $id, bool $status = TRUE): CronJob { + $job = CronJob::create([ + 'id' => $id, + 'title' => 'Job ' . $id, + 'status' => $status, + 'module' => 'system', + 'callback' => 'system_cron', + ]); + $job->save(); + + return $job; + } + + /** + * Tests that inspecting jobs raises no warning or notice. + * + * This is the regression that matters. The obvious API for this, + * CronJob::loadLatestLogEntries(), reads a property the Drupal 8+ logger + * plugins do not have, so it emits "Undefined property" on every request. A + * warning is not a \Throwable, so it cannot be caught - it just fills the + * site's log and returns a wrong answer. + * + * Scoped to warnings and notices on purpose. Ultimate Cron's own plugin + * managers raise deprecations that are none of this module's business, and + * catching those here would make the test fail for someone else's reasons. + */ + public function testInspectionRaisesNoWarning(): void { + $this->createJob('job_one'); + $this->createJob('job_two'); + + $raised = []; + $handler = static function ($severity, $message) use (&$raised) { + $raised[] = $message; + return TRUE; + }; + set_error_handler($handler, E_WARNING | E_NOTICE | E_USER_WARNING | E_USER_NOTICE); + try { + $this->inspector->findProblems(); + } + finally { + restore_error_handler(); + } + + $this->assertSame([], $raised); + } + + /** + * Tests that a job which has never run is not reported as broken. + * + * Ultimate Cron takes the same view: a job that has not run yet is not behind + * its schedule, because there is nothing to be late relative to. + */ + public function testJobThatNeverRanIsHealthy(): void { + $this->createJob('job_one'); + + $this->assertSame([], $this->inspector->findProblems()); + } + + /** + * Tests that a disabled job is ignored. + */ + public function testDisabledJobIsIgnored(): void { + $job = $this->createJob('job_one', FALSE); + $this->logRun($job, RfcLogLevel::ERROR); + + $this->assertSame([], $this->inspector->findProblems()); + } + + /** + * Tests that a job whose last run logged an error is reported. + */ + public function testFailedJobIsReported(): void { + $job = $this->createJob('job_one'); + $this->logRun($job, RfcLogLevel::ERROR, 'Boom in the importer'); + + $problems = $this->inspector->findProblems(); + + $this->assertCount(1, $problems); + $this->assertSame('job_one', $problems[0]['job']); + $this->assertSame('failed', $problems[0]['reason']); + $this->assertStringContainsString('Boom in the importer', $problems[0]['detail']); + } + + /** + * Tests that a run which started and never finished is reported. + */ + public function testUnfinishedRunIsReported(): void { + $job = $this->createJob('job_one'); + $this->logRun($job, RfcLogLevel::NOTICE, 'Started', FALSE); + + $problems = $this->inspector->findProblems(); + + $this->assertCount(1, $problems); + $this->assertSame('unfinished', $problems[0]['reason']); + } + + /** + * Tests that an excluded job is not reported. + */ + public function testExcludedJobIsIgnored(): void { + $job = $this->createJob('job_one'); + $this->logRun($job, RfcLogLevel::ERROR); + + $this->config(LogsMonitoringInterface::CONFIG_NAME) + ->set('cron.excluded_jobs', ['job_one']) + ->save(); + + $this->assertSame([], $this->inspector->findProblems()); + } + + /** + * Tests that a healthy completed run is not reported. + */ + public function testHealthyRunIsAccepted(): void { + $job = $this->createJob('job_one'); + $this->logRun($job, RfcLogLevel::NOTICE, 'All good'); + + $this->assertSame([], $this->inspector->findProblems()); + } + + /** + * Writes a log entry for a job. + * + * @param \Drupal\ultimate_cron\Entity\CronJob $job + * The job. + * @param int $severity + * The RfcLogLevel severity to record. + * @param string $message + * The message to record. + * @param bool $finished + * Whether the run completed. An unfinished run has no end time, which is + * what a fatal or a killed worker leaves behind. + */ + protected function logRun(CronJob $job, int $severity, string $message = 'ran', bool $finished = TRUE): void { + $now = $this->container->get('datetime.time')->getRequestTime(); + + $this->container->get('database')->insert('ultimate_cron_log') + ->fields([ + 'lid' => $job->id() . '-' . $now, + 'name' => $job->id(), + 'log_type' => 0, + 'start_time' => $now - 60, + 'end_time' => $finished ? $now - 59 : 0, + 'init_message' => 'Launched', + 'message' => $message, + 'severity' => $severity, + 'uid' => 0, + ]) + ->execute(); + } + +} diff --git a/scripts/drush-healthcheck.conf.example b/scripts/drush-healthcheck.conf.example new file mode 100644 index 0000000..53a59e7 --- /dev/null +++ b/scripts/drush-healthcheck.conf.example @@ -0,0 +1,34 @@ +# Example configuration for drush-healthcheck.sh. +# +# Copy to one of the locations the script looks at (see --help) and edit: +# +# cp drush-healthcheck.conf.example /etc/drush-healthcheck.conf +# +# This file is sourced by bash, so it is shell syntax, not ini. +# +# DRUPAL_ROOT, DRUSH_BIN and DRUSH_HC_SITES are required - the script exits 2 +# without them rather than guessing. Guessing is how a monitor ends up happily +# reporting on a different site than the one you meant. + +# Composer root of the project (the directory containing vendor/). +DRUPAL_ROOT="/var/www/example.com" + +# Drush binary. Usually $DRUPAL_ROOT/vendor/bin/drush. +DRUSH_BIN="/var/www/example.com/vendor/bin/drush" + +# Sites to check, comma or space separated. Use "-" for a single-site install +# (no --uri is passed). For a multisite, list the URIs Drush expects: +# DRUSH_HC_SITES="example.com, fr.example.com, de.example.com" +DRUSH_HC_SITES="-" + +# Per-command timeout in seconds, so a hung database cannot wedge cron. +DRUSH_HC_TIMEOUT=120 + +# Optional external dead man's switch (Healthchecks.io, Cronitor, an +# UptimeRobot heartbeat monitor). Curled only after every site passes. +# +# "{site}" is replaced with the site URI. It is REQUIRED when checking more than +# one site: a single shared URL cannot say which site it is reporting on, so a +# healthy site would keep the switch green while another one is dead. The script +# exits 2 rather than let that happen. +# DRUSH_HC_PING_URL="https://hc-ping.com/your-uuid-here" diff --git a/scripts/drush-healthcheck.sh b/scripts/drush-healthcheck.sh new file mode 100755 index 0000000..dad8672 --- /dev/null +++ b/scripts/drush-healthcheck.sh @@ -0,0 +1,302 @@ +#!/usr/bin/env bash +# +# drush-healthcheck.sh - proves scheduled Drush execution works on this site. +# +# Runs "drush logs-monitoring:heartbeat" for every site. That command performs +# the actual checks (bootstrap, database query, entity query) and records a +# timestamp in Drupal State; this script only handles the things bash is good +# at: locking, timeouts, iterating over a multisite and reporting exit codes. +# +# The heartbeat write is the proof. If Drush is broken the timestamp never +# updates, /admin/reports/drush-monitoring starts answering 503 and your uptime +# monitor alerts. Nothing needs to push a failure anywhere. +# +# This wrapper is optional. A single-site install can call Drush from the +# crontab directly: +# +# */15 * * * * flock -n /run/lock/lm-hb.lock timeout 120 \ +# /var/www/example.com/vendor/bin/drush logs-monitoring:heartbeat -q +# +# Exit codes: +# 0 all checks passed +# 1 a check failed (see stderr) +# 2 bad usage / configuration +# 3 another instance is already running +# +# Usage: +# drush-healthcheck.sh [options] +# +# Options: +# -r, --root PATH Drupal project root (composer root). Required. +# -d, --drush PATH Drush binary. Required. +# -s, --sites LIST Comma/space separated site URIs. Required. +# "-" means a single-site run with no --uri. +# -p, --ping-url URL Dead-man's-switch URL, curled only when every site +# passed. "{site}" is replaced by the site URI, and is +# mandatory when checking more than one site. +# -t, --timeout SECONDS Per-command timeout. Default: 120 +# -c, --config FILE Config file to source. Default: auto-detect. +# --no-state Run the checks but do not record the heartbeat. +# -q, --quiet Only output on failure. +# -h, --help Show this help. +# +# Environment variables: +# DRUPAL_ROOT, DRUSH_BIN, DRUSH_HC_SITES, DRUSH_HC_PING_URL, DRUSH_HC_TIMEOUT +# +# Config file (first found wins, unless -c is given): +# ./drush-healthcheck.conf +#