diff --git a/Deployment/master.conf.template b/Deployment/master.conf.template index c053aad..ca5f14a 100644 --- a/Deployment/master.conf.template +++ b/Deployment/master.conf.template @@ -1805,6 +1805,28 @@ # to be trusted first. This gates telling someone, which is the reason for having looked. AI_REPAIR_NOTIFY_ENABLED=true +# ━━━ AI Repair: what it reads ━━━ +# Beyond Varaverk's own logs and the arrs' health endpoints. +# +# The system log catches what Varaverk cannot see about itself — a disk throwing I/O errors, a +# filesystem going read-only, a PCIe link retraining every two minutes. Container restarts and +# OOM kills are deliberately left to docker_watchdog, which already notifies on them. +# +# Container logs catch the opposite blind spot: docker_watchdog watches whether a container is +# up and answering, which a container that has been unable to write to its database all day +# passes perfectly. Only environment faults are matched — disk full, read-only filesystem, +# corrupt database, fd limits, expired certificates — because those strings come from libc, the +# kernel and SQLite and mean the same thing in all fifty containers. Anything app-specific +# belongs in that app's own health endpoint. +# +# Both are bounded by time (since the last pass) and by a line cap, so a flood costs one pass. +# Tools/ai_log_check.sh replays this host's real logs against the patterns — run it after +# changing any of them. + AI_REPAIR_SYSLOG_ENABLED=true + AI_REPAIR_SYSLOG_MAX_LINES=4000 + AI_REPAIR_CONTAINER_LOGS_ENABLED=true + AI_REPAIR_CONTAINER_LOG_LINES=400 + # ━━━ AI Conf Write Access ━━━ # Separate switch from AI_ENABLED, off by default, and an explicit key whitelist. Never paths, # never credentials, never a container name. An empty whitelist means no writes regardless of diff --git a/Plugin/unraid/Tools/ai_log_check.php b/Plugin/unraid/Tools/ai_log_check.php new file mode 100644 index 0000000..f2c89a2 --- /dev/null +++ b/Plugin/unraid/Tools/ai_log_check.php @@ -0,0 +1,131 @@ + [$line]]); + return $f[0] ?? null; + } + $f = vv_ai_syslog_findings(0, [$line]); + return $f[0] ?? null; +} + +if ($only !== 'precision') { + echo "── recall: fixtures ──────────────────────────────────────────────\n"; + if (!is_readable($fixtures)) { + echo " FAIL cannot read $fixtures\n"; + exit(1); + } + foreach (file($fixtures, FILE_IGNORE_NEW_LINES) as $n => $raw) { + $line = rtrim($raw); + if ($line === '' || $line[0] === '#') continue; + + // A ! line must match nothing at all. ! source | line + if ($line[0] === '!') { + $rest = trim(substr($line, 1)); + $bits = explode('|', $rest, 2); + if (count($bits) !== 2) { ok(sprintf('L%d is malformed', $n + 1), false, $line); continue; } + $src = trim($bits[0]); + $sample = trim($bits[1]); + $got = classify($sample, $src); + ok(sprintf('L%-3d %s no match: %s', $n + 1, $src, mb_substr($sample, 0, 58)), + $got === null, $got ? "matched as {$got['ref']} / {$got['subject']}" : ''); + continue; + } + + $parts = explode('|', $line, 4); + if (count($parts) !== 4) { ok(sprintf('L%d is malformed', $n + 1), false, $line); continue; } + [$src, $wantSubject, $wantLevel, $sample] = array_map('trim', $parts); + + $got = classify($sample, $src); + if ($got === null) { + ok(sprintf('L%-3d %s', $n + 1, mb_substr($sample, 0, 64)), false, 'no pattern matched'); + continue; + } + ok(sprintf('L%-3d %-12s %-5s %s', $n + 1, $got['subject'], $got['sys_level'], + mb_substr($got['ref'], 0, 30)), + $got['subject'] === $wantSubject && $got['sys_level'] === $wantLevel, + sprintf('wanted %s/%s, got %s/%s', $wantSubject, $wantLevel, + $got['subject'], $got['sys_level'])); + } +} + +if ($only !== 'recall') { + echo "\n── precision: this host's real syslog history ────────────────────\n"; + $total = 0; $hits = []; + foreach (glob('/var/log/syslog*') ?: [] as $file) { + if (!is_readable($file)) continue; + $fh = @fopen($file, 'r'); + if (!$fh) continue; + while (($l = fgets($fh)) !== false) { + $total++; + $got = classify(rtrim($l)); + if ($got === null) continue; + $k = $got['ref'] . ' | ' . $got['subject'] . ' | ' . $got['sys_level']; + $hits[$k] = ($hits[$k] ?? 0) + 1; + } + fclose($fh); + } + printf(" scanned %s lines\n", number_format($total)); + if ($hits) { arsort($hits); foreach ($hits as $k => $n) printf(" %-7s %s\n", number_format($n), $k); } + else { echo " nothing matched\n"; } + + // Every running container, read far deeper than a sweep ever does. A pattern that is quiet + // over this much real output is a pattern that will be quiet in service. + echo "\n── precision: every running container's log ──────────────────────\n"; + $cTotal = 0; $hits = []; + $names = vv_ai_running_containers(); + foreach ($names as $name) { + $lines = vv_ai_container_log($name, 1, 2000); + $cTotal += count($lines); + $found = vv_ai_container_findings(0, [$name => $lines]); + foreach ($found as $f) { + $k = $f['ref'] . ' | ' . $f['subject'] . ' | ' . $f['sys_level']; + $hits[$k] = ($hits[$k] ?? 0) + (int)filter_var($f['observed'], FILTER_SANITIZE_NUMBER_INT); + } + } + printf(" scanned %s lines across %d container%s\n", number_format($cTotal), count($names), + count($names) === 1 ? '' : 's'); + if (!$hits) { + echo " nothing matched — this host is not reporting any of these faults\n"; + } else { + arsort($hits); + foreach ($hits as $k => $n) printf(" %-7s %s\n", number_format($n), $k); + echo "\n Each line above is a fault the sweep would file. If any of them is normal\n" + . " operation on this machine, the pattern is wrong — add it to the fixtures as a\n" + . " ! line and tighten the pattern until it stops matching.\n"; + } +} + +printf("\n%d passed, %d failed\n", $pass, $fail); +exit($fail ? 1 : 0); diff --git a/Plugin/unraid/Tools/ai_log_check.sh b/Plugin/unraid/Tools/ai_log_check.sh new file mode 100755 index 0000000..457d961 --- /dev/null +++ b/Plugin/unraid/Tools/ai_log_check.sh @@ -0,0 +1,28 @@ +#!/bin/bash +# ============================================================================================== +# ============================== AI Log Pattern Check ======================================= +# ============================================================================================== +# PURPOSE +# ───────────────────────────────────────────────────────────────────────────── +# Checks the repair sweep's syslog triage two ways, because the two failure modes are opposite +# and a single test catches only one of them: +# +# RECALL — every line in ai_log_fixtures.txt is recognised, with the right subject and +# the right level. Faults this host has never had, which is most of them. +# PRECISION — replays this machine's entire real syslog history and reports everything the +# patterns fire on. A pattern that matches normal operation fills the findings +# store with noise and teaches the operator to ignore the notification. +# +# Run it after touching VV_AI_SYSLOG_PATTERNS. Nothing here writes: no findings are filed, no +# conf is read for anything but the enable flag, and the sweep is never invoked. +# ============================================================================================== +# RUNTIME MODES +# ============================================================================================== +# +# ai_log_check.sh both checks +# ai_log_check.sh --precision replay the host's syslogs only, and list what matched +# ai_log_check.sh --recall fixtures only +# +# ============================================================================================== +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +php "$SCRIPT_DIR/ai_log_check.php" "$@" diff --git a/Plugin/unraid/Tools/ai_log_fixtures.txt b/Plugin/unraid/Tools/ai_log_fixtures.txt new file mode 100644 index 0000000..168b949 --- /dev/null +++ b/Plugin/unraid/Tools/ai_log_fixtures.txt @@ -0,0 +1,100 @@ +# ═══════════════════════════════════════════════════════════════════════════════════════════════ +# Log lines the repair sweep must recognise, one case per line, checked by ai_log_check.sh. +# +# WHY THIS FILE EXISTS +# The triage patterns for Varaverk's own logs were written against its emit sites — the format +# strings are in this repo and can be read. The kernel's are not, and this host is healthy: +# 74,519 lines of its real syslog contain PCIe AER errors and nothing else. So the patterns for +# a failing disk or a corrupt filesystem cannot be verified against anything this machine has +# said, and a pattern nobody has ever seen match is a pattern that does not work. +# +# These lines are what those faults look like. Precision is checked separately and against +# reality — ai_syslog_check.sh replays the host's whole syslog history and fails if anything +# fires that should not. This file is the other half: recall, on faults the host has not had. +# +# THE RULE FOR ADDING ONE +# Paste the real line, from this machine or from a kernel that emitted it. Do not compose one +# from what the pattern already matches — that tests the regex against itself and passes +# forever while the real format drifts away underneath it. +# +# FORMAT +# source | subject | level | line +# +# source sys = /var/log/syslog | ctr = a container log line +# +# subject what the finding must be about, after extraction +# level warn | error +# line the syslog line, verbatim, including its timestamp and host prefix +# +# A line beginning with ! must match NOTHING. Those are the near misses — normal operation that +# reads like a fault — and they are the reason the pattern list is not simply /error/i. +# Their format is: ! source | line +# ═══════════════════════════════════════════════════════════════════════════════════════════════ + +# ── PCIe. Verified: this host emitted 427 of these across three syslogs. ────────────────────── +sys | 0000:03:00.0 | warn | Aug 9 21:46:07 unRAID-Gmer4Lfe kernel: pcieport 0000:00:01.1: AER: Multiple Correctable error message received from 0000:03:00.0 +sys | 0000:02:02.0 | warn | Aug 7 11:02:41 unRAID-Gmer4Lfe kernel: pcieport 0000:00:03.1: AER: Correctable error message received from 0000:02:02.0 +sys | 0000:0a:00.0 | error | Aug 9 03:14:02 tower kernel: pcieport 0000:00:1c.0: AER: Uncorrected (Non-Fatal) error received from 0000:0a:00.0 +sys | 0000:0b:00.0 | error | Aug 9 03:14:03 tower kernel: pcieport 0000:00:1c.4: AER: Fatal error received from 0000:0b:00.0 + +# ── Block layer. The device is the subject; the ATA port above it is not actionable. ───────── +sys | sdo | error | Aug 9 04:21:09 tower kernel: blk_update_request: critical medium error, dev sdo, sector 1953525161 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0 +sys | sde | error | Aug 9 04:22:11 tower kernel: blk_update_request: I/O error, dev sde, sector 8 op 0x1:(WRITE) flags 0x800 phys_seg 0 prio class 0 +sys | sdc | error | Aug 9 04:23:00 tower kernel: Buffer I/O error on dev sdc, logical block 0, async page read +sys | sdo | error | Aug 9 04:24:55 tower kernel: sd 1:0:3:0: [sdo] tag#28 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE unrecovered read error + +# ── Filesystems. Each names its own device inside the parentheses. ──────────────────────────── +sys | md1 | error | Aug 9 05:00:01 tower kernel: XFS (md1): Metadata corruption detected at xfs_agf_verify+0x1f0/0x1f9 [xfs], xfs_agf block 0x1 +sys | md2 | error | Aug 9 05:01:02 tower kernel: XFS (md2): Internal error xfs_trans_cancel at line 990 of file fs/xfs/xfs_trans.c +sys | sdb1 | error | Aug 9 05:02:03 tower kernel: BTRFS error (device sdb1): parent transid verify failed on 1298432 wanted 12 found 11 +sys | sdd1 | error | Aug 9 05:03:04 tower kernel: EXT4-fs error (device sdd1): ext4_find_entry:1455: inode #2: comm ls: reading directory lblock 0 +sys | filesystem | error | Aug 9 05:04:05 tower kernel: EXT4-fs (sdd1): Remounting filesystem read-only + +# ── Memory and the kernel itself. ───────────────────────────────────────────────────────────── +sys | shfs | error | Aug 9 06:00:00 tower kernel: Out of memory: Killed process 9823 (shfs) total-vm:2451234kB, anon-rss:1923412kB +sys | mono | error | Aug 9 06:00:01 tower kernel: Out of memory: Killed process 1122 (mono) total-vm:900000kB, anon-rss:800000kB +sys | kernel | error | Aug 9 07:00:00 tower kernel: kernel BUG at fs/xfs/xfs_message.c:102! +sys | kernel | error | Aug 9 07:00:01 tower kernel: general protection fault: 0000 [#1] SMP NOPTI + +# ── Near misses. Normal operation that reads like a fault; none of these may match. ─────────── +! sys | Aug 9 04:40:01 unRAID-Gmer4Lfe kernel: md: recovery thread: exit status: 0 +! sys | Aug 9 04:40:02 unRAID-Gmer4Lfe kernel: md: sync done. time=17452sec +! sys | Aug 9 04:40:03 unRAID-Gmer4Lfe kernel: md: import disk6: (sdi) TOSHIBA_MG07ACA12TEY_Z0N0ANF9SG size: 11718885324 +! sys | Aug 9 12:00:00 unRAID-Gmer4Lfe shfs: /usr/sbin/zfs destroy 'cache/isos' 2>&1 +! sys | Aug 9 12:00:01 unRAID-Gmer4Lfe emhttpd: action: Enable all features using 'zpool upgrade'. +! sys | Aug 9 12:00:02 unRAID-Gmer4Lfe root: Fix Common Problems: Error: Docker image file is getting full +! sys | Aug 9 12:00:03 unRAID-Gmer4Lfe kernel: XFS (md1): Mounting V5 Filesystem +! sys | Aug 9 12:00:04 unRAID-Gmer4Lfe kernel: XFS (md1): Ending clean mount +! sys | Aug 9 12:00:05 unRAID-Gmer4Lfe sshd[1234]: error: kex_exchange_identification: Connection closed by remote host +! sys | Aug 9 12:00:06 unRAID-Gmer4Lfe nginx: 2026/08/09 12:00:06 [error] 1#1: *1 open() failed +! sys | Aug 9 12:00:07 unRAID-Gmer4Lfe kernel: docker0: port 3(veth1a2b3c) entered disabled state +! sys | Aug 9 12:00:08 unRAID-Gmer4Lfe kernel: eth0: Link is Down + +# ══ CONTAINER LOGS ═════════════════════════════════════════════════════════════════════════════ +# Fifty containers run here and they are fifty applications with nothing in common. These patterns +# are about the environment underneath them — the strings come from libc, the kernel and SQLite, +# so they are identical in every one. Precision was checked against all fifty containers' real +# logs: 79,180 lines, zero matches, which is what a healthy machine should produce. +# +# The subject of a container finding is the container, so it is not asserted per line here — the +# name comes from which log the line was read from, not from the text. Subject is left as the +# container name the checker supplies. + +ctr | fixture-container | error | 2026-08-09 12:00:00 ERROR sqlite3.DatabaseError: database disk image is malformed +ctr | fixture-container | error | [Errno 28] No space left on device: '/config/logs/sonarr.txt' +ctr | fixture-container | error | OSError: [Errno 30] Read-only file system: '/data/media' +ctr | fixture-container | error | sqlite3.OperationalError: database or disk is full +ctr | fixture-container | error | Error: EMFILE: too many open files, open '/config/db' +ctr | fixture-container | error | curl: (60) SSL certificate problem: certificate has expired +ctr | fixture-container | error | ssl.SSLCertVerificationError: certificate verify failed: unable to get local issuer +ctr | fixture-container | error | write /var/lib/data: disk quota exceeded +ctr | fixture-container | error | sqlite3.DatabaseError: file is not a database + +# Near misses from real arr and media-server logs. None of these may match. +! ctr | 2026-08-09 12:00:00 WARN sqlite3.OperationalError: database is locked, retrying in 200ms +! ctr | 2026-08-09 12:00:01 INFO Import failed: file already exists in the destination +! ctr | 2026-08-09 12:00:02 ERROR Permission denied reading /downloads/incomplete/foo.part +! ctr | 2026-08-09 12:00:03 WARN Certificate expires in 21 days, renewal scheduled +! ctr | 2026-08-09 12:00:04 ERROR Connection refused connecting to 127.0.0.1:9117 +! ctr | 2026-08-09 12:00:05 INFO Deleted 4 files to free space on device sda +! ctr | 2026-08-09 12:00:06 ERROR HTTP 500 while calling /api/v3/command diff --git a/Plugin/unraid/include/ai_repair.php b/Plugin/unraid/include/ai_repair.php index 9d88642..2d4cd32 100644 --- a/Plugin/unraid/include/ai_repair.php +++ b/Plugin/unraid/include/ai_repair.php @@ -83,6 +83,8 @@ const VV_AI_FINDING_KINDS = [ 'unknown_target' => 'a conf entry names a container or share that does not exist here', 'missing_value' => 'a conf key required by the job that ran is empty', 'arr_health' => 'an arr is reporting a problem about itself', + 'system_fault' => 'the kernel reported a hardware or filesystem fault about this machine', + 'container_fault' => 'a container is logging a fault about its own environment', ]; // Which kinds are a statement about Varaverk's configuration, and which are a statement about @@ -183,6 +185,14 @@ function vv_ai_finding_severity(array $f): string { return ($f['arr_type'] ?? '') === 'error' ? 'error' : 'warn'; } + // Same shape as arr_health, for the same reason: the level belongs to the pattern that + // matched, because "correctable PCIe error" and "I/O error on a disk" are the same kind of + // finding and nothing like the same news. Carried on the candidate rather than inferred here. + // Shared by both log-derived kinds — one field, because they mean exactly the same thing. + if (in_array($f['kind'] ?? '', ['system_fault', 'container_fault'], true)) { + return ($f['sys_level'] ?? '') === 'error' ? 'error' : 'warn'; + } + return match ($f['kind'] ?? '') { 'auth_rejected' => 'error', // answered and refused — nothing gets through until fixed 'missing_value' => 'error', // configured to use something that was never supplied @@ -297,8 +307,13 @@ function vv_ai_finding_write(array $f): array { // Recomputed on every sighting rather than stored once: a key that becomes a toggle, or // a toggle that is replaced by a real value, changes what this finding means. 'ref' => mb_substr($ref, 0, 120), + // Every field the grader consults has to be handed to it. It was given a hand-picked + // three, so a kind added later that grades on a fourth silently came out as a warning — + // which is how a disk throwing I/O errors would have been filed at the same level as a + // switched-off toggle, and notified as a warning rather than an alert. 'severity' => vv_ai_finding_severity(['kind' => $kind, 'conf_key' => $confKey, - 'arr_type' => (string)($f['arr_type'] ?? '')]), + 'arr_type' => (string)($f['arr_type'] ?? ''), + 'sys_level' => (string)($f['sys_level'] ?? '')]), 'host' => vv_detect_host(), 'first' => $now, 'last' => $now, @@ -478,6 +493,303 @@ function vv_ai_findings_prune(): int { return $n; } +// ── The system's own log ───────────────────────────────────────────────────────────────────── +// Everything above this reads Varaverk's logs and asks the arrs about themselves. Neither can +// see a disk throwing I/O errors, a filesystem going read-only, or a PCIe link retraining every +// two minutes — and those are the faults that explain the ones Varaverk does notice. +// +// /var/log/syslog and not dmesg. Unraid's syslog carries the kernel ring buffer's lines already, +// prefixed with `kernel:`, and it carries a real date on every line. dmesg's ring buffer wraps, +// has no persistence across a reboot, and its -T timestamps are derived from uptime rather than +// recorded, which makes "since the last pass" unanswerable from it. +// +// What is deliberately NOT here: +// Container restarts, crash loops and OOMKilled — docker_watchdog owns those and notifies on +// them, and a second opinion arriving by a second channel is not more information. +// ZFS pool health — `zpool status` answers that exactly, and inferring it from log lines when +// the authoritative command is one call away would be guessing on purpose. +// +// A host-level OOM kill IS here, and does overlap docker_watchdog when the process killed was in +// a container. They are different halves: the watchdog reports that a container restarted, this +// reports what the kernel killed and that it was memory. The store folds repeats into one row. +const VV_AI_SYSLOG_PATTERNS = [ + // Verified against this host's own syslog, which produced 109 of these in a day. Correctable + // means the link recovered, which is why it is a warning and not an error — but a device + // retraining continuously is failing slowly. + ['re' => '/AER: (?:Multiple )?Corrected error.*?(?:from|received from) (?[0-9a-f:.]+)/i', + 'level' => 'warn', 'what' => 'PCIe correctable errors'], + ['re' => '/AER: (?:Multiple )?Correctable error message received from (?[0-9a-f:.]+)/i', + 'level' => 'warn', 'what' => 'PCIe correctable errors'], + // The severity word is followed by a parenthetical often enough that requiring "error" to + // come straight after it misses the common form: "Uncorrected (Non-Fatal) error received + // from". Found by a fixture, not by reasoning about it. + ['re' => '/AER: (?:Multiple )?(?:Uncorrected|Fatal|Uncorrectable)[^:]{0,20}? error.*?from (?[0-9a-f:.]+)/i', + 'level' => 'error', 'what' => 'PCIe uncorrectable errors'], + + // Block layer. blk_update_request is where a failed read or write surfaces with the device + // named, which is the line worth keeping — the ATA exception above it names a port, not a + // disk, and a port number is not something an operator can act on. + ['re' => '/blk_update_request: (?:critical )?(?:I\/O|medium|target|nonexistent) error, dev (?[a-z0-9]+)/i', + 'level' => 'error', 'what' => 'block I/O errors'], + ['re' => '/Buffer I\/O error on dev (?[a-z0-9]+)/i', + 'level' => 'error', 'what' => 'buffer I/O errors'], + // The SCSI layer writes the device in brackets — "sd 1:0:3:0: [sdo] tag#28 FAILED" — so the + // name is not followed by a colon the way it is everywhere else. Both forms accepted. + ['re' => '/(?:\[(?sd[a-z]+|nvme\d+n\d+)\]|(?sd[a-z]+|nvme\d+n\d+):).*?(?:unrecovered read error|medium error|rejecting I\/O to|failed command)/i', + 'level' => 'error', 'what' => 'device errors'], + + // Filesystems. Each names the device inside its own parentheses, which is the identity the + // finding is keyed on — one finding per filesystem, however many lines it emits. + ['re' => '/XFS \((?[^)]+)\): (?:Metadata|Corruption|corruption|log I\/O error|writeback error|Internal error)/', + 'level' => 'error', 'what' => 'XFS errors'], + ['re' => '/BTRFS (?:error|critical) \(device (?[^)]+)\)/', + 'level' => 'error', 'what' => 'BTRFS errors'], + ['re' => '/EXT4-fs error \(device (?[^)]+)\)/', + 'level' => 'error', 'what' => 'ext4 errors'], + ['re' => '/(?:Remounting|remounting) filesystem read-only/', + 'level' => 'error', 'what' => 'a filesystem went read-only', 'subject' => 'filesystem'], + + // Memory. The process name is the subject, so "the kernel keeps killing shfs" is one finding + // rather than one per occurrence. + ['re' => '/Out of memory: Killed process \d+ \((?[^)]+)\)/', + 'level' => 'error', 'what' => 'out-of-memory kills'], + + // The kernel saying it has broken. No subject to extract that means anything, so the finding + // is about the machine. + ['re' => '/(?:kernel BUG at|general protection fault|Oops: |Kernel panic)/', + 'level' => 'error', 'what' => 'kernel faults', 'subject' => 'kernel'], +]; + +function vv_ai_syslog_path(): string { + return '/var/log/syslog'; +} + +function vv_ai_syslog_enabled(): bool { + if (!vv_ai_repair_enabled()) return false; + return strtolower(trim((string)(vv_conf_vars()['AI_REPAIR_SYSLOG_ENABLED'] ?? 'true'))) !== 'false'; +} + +function vv_ai_syslog_max_lines(): int { + $n = (int)(vv_conf_vars()['AI_REPAIR_SYSLOG_MAX_LINES'] ?? 4000); + return max(100, min(50000, $n)); +} + +// "Aug 9 21:46:07" — syslog's format carries no year, which is a real problem exactly once a +// year. Parsed against the current one, and anything landing more than a day in the future is +// read as last year's: on 1 January, December's lines would otherwise be stamped eleven months +// ahead and every one of them would look newer than the last sweep, forever. +// +// Returns null for a line that does not start with a timestamp, which is a continuation line and +// belongs to whatever preceded it. +function vv_ai_syslog_ts(string $line, ?int $now = null): ?int { + if (!preg_match('/^([A-Z][a-z]{2}\s+\d{1,2} \d{2}:\d{2}:\d{2})/', $line, $m)) return null; + $now = $now ?? time(); + $ts = strtotime($m[1] . ' ' . date('Y', $now)); + if ($ts === false) return null; + if ($ts > $now + 86400) { + $ts = strtotime($m[1] . ' ' . (int)(date('Y', $now) - 1)); + if ($ts === false) return null; + } + return $ts; +} + +// The tail of syslog, bounded twice: by the line cap and by the timestamp. The cap is applied +// first and is what stops a rotation, a boot, or a flood from turning one pass into a scan of +// the whole file. +function vv_ai_syslog_lines(int $since, ?int $maxLines = null, ?string $path = null): array { + $path = $path ?? vv_ai_syslog_path(); + if (!is_readable($path)) return []; + $max = $maxLines ?? vv_ai_syslog_max_lines(); + + $out = []; $rc = 0; + exec('tail -n ' . (int)$max . ' ' . escapeshellarg($path) . ' 2>/dev/null', $out, $rc); + if ($rc !== 0) return []; + + $now = time(); + $kept = []; + foreach ($out as $line) { + $ts = vv_ai_syslog_ts($line, $now); + // A line with no timestamp cannot be placed in time. Kept only if the line before it was + // kept, since that is what a continuation is. + if ($ts === null) { if ($kept) $kept[] = $line; continue; } + if ($ts <= $since) continue; + $kept[] = $line; + } + return $kept; +} + +// Log lines in, finding candidates out. One candidate per (pattern, subject) however many lines +// matched, with the count carried in the evidence — a disk that threw four hundred I/O errors in +// a quarter of an hour is one fault, and four hundred findings would be four hundred ways to +// miss it. +function vv_ai_syslog_findings(int $since, ?array $lines = null): array { + if (!vv_ai_syslog_enabled()) return []; + $lines = $lines ?? vv_ai_syslog_lines($since); + if (!$lines) return []; + + $agg = []; + foreach ($lines as $line) { + foreach (VV_AI_SYSLOG_PATTERNS as $p) { + if (!preg_match($p['re'], $line, $m)) continue; + + // subject2 is the second branch of an alternation. PHP refuses two groups with the + // same name in one pattern, so a pattern that can find its subject in either of two + // shapes has to name them apart and try both here. + $subject = trim((string)($m['subject'] ?? '')); + if ($subject === '') $subject = trim((string)($m['subject2'] ?? '')); + if ($subject === '') $subject = trim((string)($p['subject'] ?? '')); + if ($subject === '') $subject = 'system'; + + $key = $p['what'] . '|' . $subject; + if (!isset($agg[$key])) { + $agg[$key] = ['what' => $p['what'], 'subject' => $subject, 'level' => $p['level'], + 'count' => 0, 'first_line' => trim($line)]; + } + $agg[$key]['count']++; + // The worst level wins when two patterns describe the same subject. + if ($p['level'] === 'error') $agg[$key]['level'] = 'error'; + break; // one pattern per line; the list is ordered most specific first + } + } + + $found = []; + foreach ($agg as $a) { + $found[] = [ + 'kind' => 'system_fault', + 'subject' => $a['subject'], + // What identifies it: the class of fault, not the message. The wording of a kernel + // line changes between releases and the fault does not. + 'ref' => $a['what'], + 'conf_key' => '', + 'conf_file' => '', + 'sys_level' => $a['level'], + 'observed' => $a['count'] . ' since the last pass', + 'evidence' => sprintf('%s on %s — %d line%s since the last pass. First: %s', + $a['what'], $a['subject'], $a['count'], + $a['count'] === 1 ? '' : 's', + mb_substr($a['first_line'], 0, 200)), + 'source_log' => vv_ai_syslog_path(), + // Nothing here is repairable from conf, so it goes straight to the operator rather + // than sitting open waiting for a probe that will never run. + 'state' => 'needs_operator', + ]; + } + return $found; +} + +// ── What the containers are saying ─────────────────────────────────────────────────────────── +// docker_watchdog watches container *state* — is it up, does its port answer, is it restarting. +// None of that reads a line the application wrote, so a container that is running perfectly and +// has been unable to write to its database for a day looks completely healthy from out there. +// +// The patterns are deliberately about the container's environment rather than its behaviour. +// Fifty containers run here and they are fifty different applications; there is no useful shared +// vocabulary for "this app is malfunctioning". There is an exact shared vocabulary for "the disk +// is full", "the filesystem is read-only" and "my database is corrupt", because those come from +// libc, the kernel and SQLite rather than from the application — the same string in every one of +// them. Anything app-specific belongs in that app's own health endpoint, which is where the arr +// checks already come from. +// +// Noise is the whole risk here. Every pattern below was run against the real logs of all fifty +// containers on this host before being kept; see Tools/ai_container_check.sh. +const VV_AI_CONTAINER_PATTERNS = [ + ['re' => '/no space left on device/i', + 'level' => 'error', 'what' => 'disk full'], + ['re' => '/read-only file ?system|Read-only file system/i', + 'level' => 'error', 'what' => 'read-only filesystem'], + ['re' => '/disk quota exceeded/i', + 'level' => 'error', 'what' => 'disk quota exceeded'], + // SQLite's own wording. "database is locked" is deliberately absent: it is contention, it is + // transient, and the arrs emit it in normal operation. + ['re' => '/database disk image is malformed|database or disk is full|file is (?:not a database|encrypted or is not a database)/i', + 'level' => 'error', 'what' => 'database corruption'], + ['re' => '/too many open files/i', + 'level' => 'error', 'what' => 'file descriptor limit'], + ['re' => '/certificate has expired|certificate is not yet valid|certificate verify failed/i', + 'level' => 'error', 'what' => 'certificate problems'], +]; + +function vv_ai_container_logs_enabled(): bool { + if (!vv_ai_repair_enabled()) return false; + return strtolower(trim((string)(vv_conf_vars()['AI_REPAIR_CONTAINER_LOGS_ENABLED'] ?? 'true'))) !== 'false'; +} + +function vv_ai_container_log_lines(): int { + $n = (int)(vv_conf_vars()['AI_REPAIR_CONTAINER_LOG_LINES'] ?? 400); + return max(50, min(5000, $n)); +} + +// Running containers only. A stopped one has nothing new to say, and its last words before it +// stopped are docker_watchdog's business. +function vv_ai_running_containers(): array { + $out = []; $rc = 0; + exec('docker ps --format {{.Names}} 2>/dev/null', $out, $rc); + if ($rc !== 0) return []; + return array_values(array_filter(array_map('trim', $out), fn($n) => $n !== '')); +} + +// One container's log since the marker, bounded by both a time and a line count. --since alone +// is not a bound: a container that logged a million lines in the last quarter hour would hand +// back all of them. +function vv_ai_container_log(string $name, int $since, ?int $maxLines = null): array { + if (!preg_match('/^[A-Za-z0-9][A-Za-z0-9_.-]*$/', $name)) return []; + $max = $maxLines ?? vv_ai_container_log_lines(); + + // Both streams: applications disagree about which one an error belongs on, and several of + // these write everything to stdout. + $cmd = 'docker logs --since ' . escapeshellarg((string)max(1, $since)) + . ' --tail ' . (int)$max . ' ' . escapeshellarg($name) . ' 2>&1'; + $out = []; $rc = 0; + exec($cmd, $out, $rc); + return $rc === 0 ? $out : []; +} + +// Same aggregation as the syslog pass: one candidate per (container, fault class), with the +// count in the evidence rather than a finding per line. +function vv_ai_container_findings(int $since, ?array $logsByContainer = null): array { + if ($logsByContainer === null && !vv_ai_container_logs_enabled()) return []; + + $agg = []; + $names = $logsByContainer !== null ? array_keys($logsByContainer) : vv_ai_running_containers(); + + foreach ($names as $name) { + $lines = $logsByContainer !== null ? $logsByContainer[$name] + : vv_ai_container_log($name, $since); + foreach ($lines as $line) { + foreach (VV_AI_CONTAINER_PATTERNS as $p) { + if (!preg_match($p['re'], $line)) continue; + $key = $name . '|' . $p['what']; + if (!isset($agg[$key])) { + $agg[$key] = ['name' => $name, 'what' => $p['what'], 'level' => $p['level'], + 'count' => 0, 'first_line' => trim($line)]; + } + $agg[$key]['count']++; + break; + } + } + } + + $found = []; + foreach ($agg as $a) { + $found[] = [ + 'kind' => 'container_fault', + 'subject' => $a['name'], + 'ref' => $a['what'], + 'conf_key' => '', + 'conf_file' => '', + 'sys_level' => $a['level'], + 'observed' => $a['count'] . ' since the last pass', + 'evidence' => sprintf('%s in %s — %d line%s since the last pass. First: %s', + $a['what'], $a['name'], $a['count'], + $a['count'] === 1 ? '' : 's', + mb_substr($a['first_line'], 0, 200)), + 'source_log' => 'docker logs ' . $a['name'], + 'state' => 'needs_operator', + ]; + } + return $found; +} + // ── Reaching the operator ──────────────────────────────────────────────────────────────────── // A finding nobody is told about is a finding nobody has. The card on the AI tab shows them, but // only to someone who opens the tab, and the point of this subsystem is that it works while @@ -664,10 +976,16 @@ function vv_ai_repair_sweep(bool $dryRun = false): array { $sum = ['ok' => true, 'runs' => count($runs), 'findings' => 0, 'fixed' => 0, 'needs_operator' => 0, 'resolved' => 0, 'quiet' => 0, 'details' => []]; - // Candidates from two sources. Log triage is bounded to runs that finished since the last + // Candidates from three sources. Log triage is bounded to runs that finished since the last // pass; the arrs are asked every time, because their health is a current state rather than // something that appeared in a log once. Asking costs three local HTTP calls. + // + // The system log is bounded the same way the run logs are — everything since the marker — + // so a fault that has been shouting for an hour is counted once per pass rather than once + // per line, and stops producing candidates the moment it stops being logged. $candidates = vv_ai_arr_health_findings(); + foreach (vv_ai_syslog_findings($since) as $c) $candidates[] = $c; + foreach (vv_ai_container_findings($since) as $c) $candidates[] = $c; foreach ($runs as $run) { $lines = vv_ai_run_log_lines($run['log'], $run['start']);