| 1 |
<?php |
| 2 |
|
| 3 |
if (!defined('ABSPATH')) { |
| 4 |
exit; |
| 5 |
} |
| 6 |
|
| 7 |
/** |
| 8 |
* Debug-log tail scanner + PII-stripping signature normalizer for the |
| 9 |
* feedback payload's `recent_error_signatures` field. |
| 10 |
* |
| 11 |
* Two responsibilities both anchored to the debug log: |
| 12 |
* 1. probeRecentErrorSignatures(): tail-read the plugin debug log |
| 13 |
* (capped at 256 KB), parse lines matching the canonical |
| 14 |
* "YYYY-MM-DD HH:MM:SS [TZ] (LEVEL): ..." shape that Logging.php emits, |
| 15 |
* keep only [ERROR]/[WARN] entries within the last 7 days, group |
| 16 |
* by coarse signature, return the top 5 by count. |
| 17 |
* 2. normalizeErrorSignature(): the PII-stripping transform that |
| 18 |
* makes the grouping correct. Cuts the per-request/environment |
| 19 |
* envelope the plugin's own writer appends (referrer, requested |
| 20 |
* URL, versions, query duration), folds body-embedded wall-clock |
| 21 |
* stamps, strips absolute paths to basenames, collapses memory |
| 22 |
* addresses, hex literals, multi-digit numbers, and whitespace runs |
| 23 |
* so different incident timestamps and addresses fold into the same |
| 24 |
* signature key. This is the unit pinned by |
| 25 |
* tests/F6UrlFragmentLeakIntoErrorSignatureTest, and the grouping |
| 26 |
* POLICY it implements is pinned against the shared corpus in |
| 27 |
* tests/ErrorSignatureGroupingCorpusTest -- shared because the |
| 28 |
* report server implements the same policy a second time, in JS |
| 29 |
* (404-solution-server src/lib/fingerprint.js). |
| 30 |
* |
| 31 |
* Owned by ABJ_404_Solution_FeedbackEnvironmentExtras via composition; |
| 32 |
* see that class's collect() method for the recordProbe() wrapper that |
| 33 |
* converts a thrown scan failure into a recent_error_signatures_error |
| 34 |
* marker slug. |
| 35 |
*/ |
| 36 |
class ABJ_404_Solution_FeedbackEnvironmentExtras_DebugLogSignatures { |
| 37 |
|
| 38 |
/** |
| 39 |
* Severity words that must never be consumed as a timezone abbreviation |
| 40 |
* while folding an embedded wall-clock stamp. |
| 41 |
*/ |
| 42 |
const LOG_LEVEL_WORDS = 'ERROR|FATAL|WARN|WARNING|INFO|DEBUG|NOTICE|TRACE'; |
| 43 |
|
| 44 |
/** |
| 45 |
* The per-request/environment tail the plugin's own writer appends, which |
| 46 |
* is not part of the defect. Two anchors, both requiring the ", <field>:" |
| 47 |
* shape so prose that merely mentions the words cannot trigger a cut: |
| 48 |
* |
| 49 |
* ", PHP version: X, WP ver: ..." -- ABJ_404_Solution_LoggingMessageWriter |
| 50 |
* ::writeErrorMessage() appends this to EVERY error line, and the |
| 51 |
* "Referrer:" / "Requested URL:" fields inside it change on every hit. |
| 52 |
* The anchor spans two adjacent fields, so a message whose own body says |
| 53 |
* "PHP version: 8.3.33 is below the minimum" keeps it. |
| 54 |
* |
| 55 |
* ", Execution time: ..." / ", execution_time: ..." -- |
| 56 |
* ABJ_404_Solution_DatabaseSqlErrorReporter puts the query duration |
| 57 |
* there, followed only by DB ver, the server-variable dump and the |
| 58 |
* stripped query. Everything identifying the failure (the driver error, |
| 59 |
* the SQL file, the route) sits before it. |
| 60 |
* |
| 61 |
* Every value cut here already travels in its own payload field, so no |
| 62 |
* triage information is lost -- and the referrer/requested URL leave the |
| 63 |
* telemetry payload entirely, which shrinks its PII surface. |
| 64 |
*/ |
| 65 |
const REQUEST_ENVELOPE_PATTERN = |
| 66 |
'/,\s*(?:execution[ _]time\s*:|PHP version\s*:\s*\S+\s*,\s*WP ver\s*:).*$/is'; |
| 67 |
|
| 68 |
/** |
| 69 |
* A wall-clock stamp embedded in the message BODY, in any zone form the |
| 70 |
* plugin or the host can emit (named abbreviation, abbreviation plus |
| 71 |
* offset, bare offset, ISO "Z", or none). At most ONE zone token is |
| 72 |
* consumed and it may not be a severity word, so |
| 73 |
* "... 03:20:01 ERROR ..." cannot lose its level. |
| 74 |
* |
| 75 |
* The leading log stamp never reaches here (probeRecentErrorSignatures() |
| 76 |
* consumes it as capture group 1), but a body can carry its own: see |
| 77 |
* ABJ_404_Solution_OldPermalinkPostResolver, which warns with the offending |
| 78 |
* post_date interpolated. The pre-existing "\d{4,}" fold only collapsed |
| 79 |
* such a value's YEAR ("2026-08-17 03:22:41" -> "N-08-17 03:22:41"), which |
| 80 |
* left a per-occurrence splitter behind. |
| 81 |
*/ |
| 82 |
const EMBEDDED_DATETIME_PATTERN = |
| 83 |
'/\b\d{4}-\d{2}-\d{2}[ T]\d{2}:\d{2}:\d{2}(?:\.\d+)?' |
| 84 |
. '(?:Z\b|\s+(?:(?!(?:' . self::LOG_LEVEL_WORDS . ')\b)[A-Z]{2,5}(?:[+-]\d{2}:?\d{2})?' |
| 85 |
. '|[+-]\d{2}(?::?\d{2})?))?/'; |
| 86 |
|
| 87 |
/** |
| 88 |
* Top distinct recurring error signatures from the plugin's debug |
| 89 |
* log file over the last 7 days, capped at 5 entries. The triggering |
| 90 |
* error is captured by the report itself ('error_signature' on the |
| 91 |
* payload); this probe captures the recurring error which is often |
| 92 |
* different and would never reach the email-on-first-error path. |
| 93 |
* |
| 94 |
* Bounded cost: reads the tail 256 KB of the debug file, parses |
| 95 |
* lines matching the canonical "YYYY-MM-DD HH:MM:SS [TZ] (LEVEL): ..." |
| 96 |
* shape, keeps only [ERROR]/[WARN] entries within the last 7 days, |
| 97 |
* groups by a coarse signature (first 200 chars after the level), |
| 98 |
* keeps the top 5 by count. Returns an empty array on any read |
| 99 |
* failure. |
| 100 |
* |
| 101 |
* Shape: |
| 102 |
* [ {signature: string, count: int, last_seen_at: int}, ... ] |
| 103 |
* |
| 104 |
* An absent, unreadable, or error-free log yields an empty array: on a |
| 105 |
* healthy site that is the truthful answer. A MISSING LOGGING SERVICE |
| 106 |
* throws instead, so the caller's recordProbe() wrapper writes a |
| 107 |
* `recent_error_signatures_error` marker. Those two cases used to be |
| 108 |
* indistinguishable in the payload -- the same "silently degrade to empty |
| 109 |
* after the thing I observe is refactored away" shape that left |
| 110 |
* `view_build_state` looking healthy-but-empty for seven weeks |
| 111 |
* (t_260801_071502_922). A probe that cannot look must never report |
| 112 |
* "nothing to see". |
| 113 |
* |
| 114 |
* @return array<int, array<string, mixed>> |
| 115 |
*/ |
| 116 |
public function probeRecentErrorSignatures(): array { |
| 117 |
$out = array(); |
| 118 |
$log = function_exists('abj_service_optional') ? abj_service_optional('logging') : null; |
| 119 |
if (!is_object($log) || !method_exists($log, 'getDebugFilePath')) { |
| 120 |
throw new \RuntimeException('logging service unavailable for recent_error_signatures probe'); |
| 121 |
} |
| 122 |
$path = (string)$log->getDebugFilePath(); |
| 123 |
if ($path === '' || !is_file($path) || !is_readable($path)) { |
| 124 |
return $out; |
| 125 |
} |
| 126 |
$size = @filesize($path); |
| 127 |
if ($size === false || $size === 0) { |
| 128 |
return $out; |
| 129 |
} |
| 130 |
$readBytes = 262144; // 256 KB |
| 131 |
$offset = $size > $readBytes ? $size - $readBytes : 0; |
| 132 |
$fh = @fopen($path, 'rb'); |
| 133 |
if (!is_resource($fh)) { |
| 134 |
return $out; |
| 135 |
} |
| 136 |
$tail = ''; |
| 137 |
try { |
| 138 |
if ($offset > 0) { |
| 139 |
@fseek($fh, $offset); |
| 140 |
// Discard the partial first line so we only group on whole records. |
| 141 |
@fgets($fh); |
| 142 |
} |
| 143 |
$chunk = @fread($fh, $readBytes); |
| 144 |
if (is_string($chunk)) { |
| 145 |
$tail = $chunk; |
| 146 |
} |
| 147 |
} finally { |
| 148 |
@fclose($fh); |
| 149 |
} |
| 150 |
if ($tail === '') { |
| 151 |
return $out; |
| 152 |
} |
| 153 |
$cutoff = abj_clock()->now() - 7 * 86400; |
| 154 |
$byKey = array(); |
| 155 |
$lines = preg_split('/\r?\n/', $tail); |
| 156 |
if (!is_array($lines)) { |
| 157 |
return $out; |
| 158 |
} |
| 159 |
foreach ($lines as $line) { |
| 160 |
if (!is_string($line) || $line === '') { continue; } |
| 161 |
// Match "YYYY-MM-DD HH:MM:SS [TZ] (LEVEL): tail..." per |
| 162 |
// LogTimestampFormatter's actual 'Y-m-d H:i:s T' output (the |
| 163 |
// trailing timezone abbreviation/offset is optional in the |
| 164 |
// pattern so older or hand-edited log lines without one still |
| 165 |
// match). |
| 166 |
if (!preg_match('/^(\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2})(?:\s+\S+)?\s+\((ERROR|WARN)\):\s*(.*)$/', $line, $m)) { |
| 167 |
continue; |
| 168 |
} |
| 169 |
// The captured datetime is in the WP site's configured timezone |
| 170 |
// (LogTimestampFormatter's contract), not PHP's default timezone, |
| 171 |
// so it must be interpreted the same way here before comparing |
| 172 |
// against the true-UTC $cutoff -- otherwise a non-UTC site's |
| 173 |
// recent errors are silently miscounted as too old (or too new). |
| 174 |
try { |
| 175 |
$ts = (new DateTimeImmutable($m[1], ABJ_404_Solution_SiteTimezone::resolve()))->getTimestamp(); |
| 176 |
} catch (Exception $e) { |
| 177 |
// The regex above validates digit *shape* (\d{4}-\d{2}-\d{2} |
| 178 |
// \d{2}:\d{2}:\d{2}) but not calendar validity, so a |
| 179 |
// corrupted or hand-edited log line (e.g. month 13) can still |
| 180 |
// reach here. Rare, but a run of these would indicate log |
| 181 |
// corruption or a LogTimestampFormatter regression, so make |
| 182 |
// it visible in diagnostics instead of dropping it with zero |
| 183 |
// trace. Delegated to a helper (rather than inlined here) to |
| 184 |
// keep this already-complex parsing loop's branch count from |
| 185 |
// growing further. |
| 186 |
$this->logUnparseableTimestamp($log, $m[1], $e); |
| 187 |
continue; |
| 188 |
} |
| 189 |
if ($ts < $cutoff) { continue; } |
| 190 |
$level = $m[2]; |
| 191 |
$msg = trim($m[3]); |
| 192 |
if ($msg === '') { continue; } |
| 193 |
$sig = $level . ':' . substr($this->normalizeErrorSignature($msg), 0, 200); |
| 194 |
if (!isset($byKey[$sig])) { |
| 195 |
$byKey[$sig] = array('signature' => $sig, 'count' => 0, 'last_seen_at' => 0); |
| 196 |
} |
| 197 |
$byKey[$sig]['count']++; |
| 198 |
if ($ts > $byKey[$sig]['last_seen_at']) { |
| 199 |
$byKey[$sig]['last_seen_at'] = $ts; |
| 200 |
} |
| 201 |
} |
| 202 |
if (empty($byKey)) { |
| 203 |
return $out; |
| 204 |
} |
| 205 |
$list = array_values($byKey); |
| 206 |
usort($list, function ($a, $b) { |
| 207 |
$cmp = $b['count'] - $a['count']; |
| 208 |
if ($cmp !== 0) { return $cmp; } |
| 209 |
return $b['last_seen_at'] - $a['last_seen_at']; |
| 210 |
}); |
| 211 |
return array_slice($list, 0, 5); |
| 212 |
} |
| 213 |
|
| 214 |
/** |
| 215 |
* Report a log line whose timestamp matched the digit-shape regex but |
| 216 |
* failed to parse as a real calendar date/time (e.g. month 13). Debug |
| 217 |
* mode gated (via Logging::debugMessage()'s own contract) since this can |
| 218 |
* run once per matched line in the tail and a corrupted log could |
| 219 |
* otherwise flood the debug log on every probe call. |
| 220 |
* |
| 221 |
* @param object $log Already validated as an object with getDebugFilePath() |
| 222 |
* by the caller; debugMessage() itself is checked here |
| 223 |
* since not every logger double implements it. |
| 224 |
* @param string $rawTimestamp The unparseable captured group, for context. |
| 225 |
* @param \Exception $e |
| 226 |
* @return void |
| 227 |
*/ |
| 228 |
private function logUnparseableTimestamp($log, string $rawTimestamp, \Exception $e): void { |
| 229 |
if (method_exists($log, 'debugMessage')) { |
| 230 |
$log->debugMessage('FeedbackEnvironmentExtras_DebugLogSignatures: unparseable log timestamp "' . |
| 231 |
$rawTimestamp . '": ' . $e->getMessage()); |
| 232 |
} |
| 233 |
} |
| 234 |
|
| 235 |
/** |
| 236 |
* Coarse-grain an error message so different incident timestamps, |
| 237 |
* memory addresses, file paths, and line numbers fold into the same |
| 238 |
* signature. Used by probeRecentErrorSignatures to group recurring |
| 239 |
* errors. Exposed (public) so the unit test |
| 240 |
* tests/F6UrlFragmentLeakIntoErrorSignatureTest can pin the |
| 241 |
* PII-stripping behavior directly. |
| 242 |
* |
| 243 |
* Mirrors ABJ_404_Solution_CrashBeacon::lightRedact() (the cheap |
| 244 |
* capture-time version run inside the fatal handler) and is also run |
| 245 |
* again on an already-lightRedact'd message at report time |
| 246 |
* (CrashBeaconReporter::buildSignature()), so the digit fold here must |
| 247 |
* use the same "bytes" exemption or the capture-time fix has no effect |
| 248 |
* on the final reported text. See lightRedact()'s docblock: a byte |
| 249 |
* count is never PII and is the memory_limit/allocation-size |
| 250 |
* diagnostic the crash-beacon feature exists to report. It is also |
| 251 |
* stable per site (memory_limit does not change between requests), so |
| 252 |
* exempting it does not hurt the grouping this function exists for. |
| 253 |
* |
| 254 |
* DELIBERATELY not normalized, and each one is a divergence from the |
| 255 |
* server-side twin (404-solution-server src/lib/fingerprint.js) that the |
| 256 |
* shared corpus records rather than tries to reconcile: |
| 257 |
* - Runs of 4 or 5 digits stay folded to "N" (the server keeps them and |
| 258 |
* folds only 6+). This output ships as readable text in the telemetry |
| 259 |
* payload, so folding post / redirect / user ids is a PII control, not |
| 260 |
* a grouping choice, and loosening it would make previously redacted |
| 261 |
* values visible. |
| 262 |
* - Source line numbers. The only carrier here is the crash beacon, |
| 263 |
* which already reports file and line as their own fields. |
| 264 |
* |
| 265 |
* @param string $msg |
| 266 |
* @return string |
| 267 |
*/ |
| 268 |
public function normalizeErrorSignature(string $msg): string { |
| 269 |
$s = $msg; |
| 270 |
// Cut the per-request/environment envelope first: it is the largest |
| 271 |
// and most variable part, and removing it also keeps the caller's |
| 272 |
// 200-char signature window for message text that discriminates. |
| 273 |
$s = preg_replace(self::REQUEST_ENVELOPE_PATTERN, '', $s) ?? $s; |
| 274 |
// Fold body-embedded wall-clock stamps before the digit fold below, |
| 275 |
// which would otherwise eat the year and leave the rest standing. |
| 276 |
$s = preg_replace(self::EMBEDDED_DATETIME_PATTERN, '[TS]', $s) ?? $s; |
| 277 |
// Strip absolute paths to just the basename. |
| 278 |
$s = preg_replace('#/[A-Za-z0-9_\-\./]+/([A-Za-z0-9_\-]+\.php)#', '$1', $s) ?? $s; |
| 279 |
// Collapse memory addresses, hex, and digit sequences. |
| 280 |
$s = preg_replace('/\b0x[0-9a-fA-F]+\b/', '0xN', $s) ?? $s; |
| 281 |
$s = preg_replace('/\b\d{4,}\b(?!\s*bytes\b)/i', 'N', $s) ?? $s; |
| 282 |
// Collapse runs of whitespace. |
| 283 |
$s = preg_replace('/\s+/', ' ', $s) ?? $s; |
| 284 |
return trim($s); |
| 285 |
} |
| 286 |
} |
| 287 |
|
