Read the system log and the containers, not only Varaverk's own logs

Triage could see what Varaverk wrote about itself and what the arrs said about themselves, and nothing else — so a disk throwing I/O errors, a filesystem going read-only or a PCIe link retraining every two minutes was invisible to the thing whose job is noticing. Container state was already watched; no line any container actually wrote ever was. Container patterns match the environment rather than the application. Fifty containers are fifty programs with no shared vocabulary for malfunctioning, but an exact shared one for a full disk or a corrupt SQLite file, because those strings come from libc and SQLite rather than from the app. Both halves are checked by Tools/ai_log_check.sh, which is two tests because the failure modes are opposite: fixtures for recall on faults this host has never had, and a replay of its real logs for precision — 74,519 syslog lines and 79,193 container lines, matching only the PCIe errors it genuinely has. Severity was being graded from a hand-picked three fields, so every one of these would have been filed as a warning however bad it was, and notified as one.
2026-08-09 22:16:04 -04:00
parent 91357a2d03
commit 426ca2e5c7
5 changed files with 601 additions and 2 deletions
@@ -0,0 +1,131 @@
+<?php
+// ═══════════════════════════════════════════════════════════════════════════════════════════════
+// PURPOSE
+//   Recall and precision for the syslog triage patterns. See ai_log_check.sh for why both
+//   halves exist and why neither alone is enough.
+//
+// OPERATIONAL MODEL
+//   Reads ai_log_fixtures.txt and this host's /var/log/syslog*. Files nothing, writes nothing,
+//   and calls no part of the sweep beyond vv_ai_syslog_findings() on lines it supplies itself.
+//
+// EXIT
+//   0 when every fixture is recognised as written. Precision findings are reported but never
+//   fail the run: what a real syslog contains is a fact about the machine, not about the
+//   patterns, and a genuinely failing disk should not turn this into a red test.
+// ═══════════════════════════════════════════════════════════════════════════════════════════════
+require_once dirname(__DIR__) . '/include/ai_repair.php';
+
+$args      = array_slice($argv ?? [], 1);
+$only      = in_array('--precision', $args, true) ? 'precision'
+           : (in_array('--recall', $args, true) ? 'recall' : 'both');
+$fixtures  = __DIR__ . '/ai_log_fixtures.txt';
+
+$pass = 0; $fail = 0;
+function ok(string $what, bool $cond, string $got = ''): void {
+    global $pass, $fail;
+    if ($cond) { $pass++; printf("  ok   %s\n", $what); }
+    else       { $fail++; printf("  FAIL %s%s\n", $what, $got !== '' ? "\n         → $got" : ''); }
+}
+
+// One line at a time, so a fixture is asserted on its own rather than on whatever aggregated
+// with it. The finders are given the line directly, bypassing the file, the timestamp filter and
+// docker — those are tested separately, and a fixture dated last August would otherwise be
+// silently dropped for being older than the marker.
+function classify(string $line, string $source = 'sys'): ?array {
+    if ($source === 'ctr') {
+        $f = vv_ai_container_findings(0, ['fixture-container' => [$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);
@@ -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" "$@"
@@ -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