404-solution / includes / diagnostics / AjaxTraceJournal.php

AjaxTraceJournal.php in 404 Solution trunk, at includes/diagnostics/AjaxTraceJournal.php

402 lines 16.4 KB

Raw Download Zip

1	<?php
2
3	if (!defined('ABSPATH')) {
4	exit;
5	}
6
7	/**
8	* Durable write-ahead storage and retention for AJAX trace records.
9	*
10	* Records are appended and flushed to a request-local pending spool as they
11	* happen, then promoted whole into one bounded, rotated JSONL journal. The
12	* spool is what survives a hard worker kill: a request that never reaches
13	* PHP shutdown leaves its file behind, and a later request recovers it into
14	* the journal rather than losing the last thing that request was doing.
15	*
16	* This class holds the retention policy and nothing else. It makes no
17	* decision about WHAT is worth recording -- callers hand it fully formed
18	* records -- which is deliberate: the beta.1 flight recorder failed because
19	* a retention rule (delete fast-completing requests) silently erased the
20	* evidence of the very requests under investigation. Retention now has one
21	* home, one test surface, and exactly one bound: rotation.
22	*/
23	final class ABJ_404_Solution_AjaxTraceJournal {
24
25	const JOURNAL_FILE = 'abj404_ajax_stage_trace.jsonl';
26	const ROTATED_FILE = 'abj404_ajax_stage_trace.old.jsonl';
27	const LOCK_FILE = 'abj404_ajax_stage_trace.lock';
28	const PENDING_GLOB = 'abj404_ajax_trace_*.pending.jsonl';
29	const RECOVER_PENDING_AFTER_SECONDS = 300;
30	const MAX_JOURNAL_BYTES = 524288;
31	const MAX_PENDING_BYTES = 32768;
32	const PROMOTION_LOCK_WAIT_TIMEOUT_US = 50000;
33
34	/**
35	* Share of the support payload's excerpt field this journal may claim.
36	* Smaller than the checkpoint journal's because a request costs ~11 stage
37	* records here against ~27 checkpoints. The per-section budgets are proven
38	* to sum inside the report contract by SupportExcerptBudgetContractTest.
39	*/
40	const MAX_SUPPORT_EXCERPT_BYTES = 49152;
41
42	/** @var string Trace directory, with a trailing separator. */
43	private $directory;
44	/** @var string */
45	private $pendingPath;
46	/** @var ABJ_404_Solution_Clock */
47	private $clock;
48	/** @var bool One failure report per request; a broken directory must not flood the debug log. */
49	private $failureReported = false;
50
51	public function __construct(string $directory, string $pendingPath, ABJ_404_Solution_Clock $clock) {
52	$this->directory = $directory;
53	$this->pendingPath = $pendingPath;
54	$this->clock = $clock;
55	}
56
57	public function pendingPath(): string {
58	return $this->pendingPath;
59	}
60
61	/**
62	* Append one fully formed record to the pending spool and flush it, so
63	* the record survives a kill that never reaches PHP shutdown.
64	*
65	* @param array<string, mixed> $record
66	*/
67	public function append(array $record): void {
68	if (@is_file($this->pendingPath)) {
69	$size = @filesize($this->pendingPath);
70	if (is_int($size) && $size >= self::MAX_PENDING_BYTES) {
71	$this->reportFailure('AJAX pending trace reached its size limit: ' . $this->pendingPath);
72	return;
73	}
74	}
75	$this->appendJsonLine($this->pendingPath, $record);
76	}
77
78	/**
79	* Move the whole pending spool into the durable journal, rotating first
80	* when the append would cross the size bound. Every request is promoted:
81	* there is no outcome-based retention.
82	*/
83	public function promote(): void {
84	if (!@is_file($this->pendingPath)) {
85	return;
86	}
87	$lock = @fopen($this->directory . self::LOCK_FILE, 'cb');
88	if ($lock === false) {
89	$this->reportFailure('AJAX trace journal lock could not be opened. Pending evidence remains at '
90	. $this->pendingPath);
91	return;
92	}
93	if (!$this->acquirePromotionLock($lock)) {
94	@fclose($lock);
95	$this->reportFailure('AJAX trace journal lock wait exceeded. Pending evidence remains at '
96	. $this->pendingPath);
97	return;
98	}
99	try {
100	$contents = @file_get_contents($this->pendingPath);
101	if (!is_string($contents)) {
102	$this->reportFailure('AJAX pending trace could not be read: ' . $this->pendingPath);
103	return;
104	}
105	$journal = $this->directory . self::JOURNAL_FILE;
106	$size = @filesize($journal);
107	if (is_int($size) && ($size + strlen($contents)) > self::MAX_JOURNAL_BYTES) {
108	$old = $this->directory . self::ROTATED_FILE;
109	if (@is_file($old) && !@unlink($old)) {
110	$this->reportFailure('AJAX rotated trace could not be removed: ' . $old);
111	return;
112	}
113	if (@is_file($journal) && !@rename($journal, $old)) {
114	$this->reportFailure('AJAX trace journal rotation failed: ' . $journal);
115	return;
116	}
117	}
118	$written = @file_put_contents($journal, $contents, FILE_APPEND \| LOCK_EX);
119	if ($written === false) {
120	$this->reportFailure('AJAX trace journal append failed: ' . $journal);
121	return;
122	}
123	$this->removePending();
124	} finally {
125	@flock($lock, LOCK_UN);
126	@fclose($lock);
127	}
128	}
129
130	/**
131	* Promote spools left behind by workers that died without running PHP
132	* shutdown. Each one is annotated with how it ended before promotion, so
133	* a reader can tell "the request was killed here" apart from "the
134	* request finished here".
135	*/
136	public function recoverAbandoned(): void {
137	$matches = glob($this->directory . self::PENDING_GLOB);
138	$cutoff = $this->clock->now() - self::RECOVER_PENDING_AFTER_SECONDS;
139	$ownPending = $this->pendingPath;
140	foreach (is_array($matches) ? $matches : array() as $path) {
141	$modified = @filemtime($path);
142	if ($modified === false \|\| $modified > $cutoff) {
143	continue;
144	}
145	$this->pendingPath = $path;
146	$handle = @fopen($path, 'rb');
147	$firstLine = is_resource($handle) ? @fgets($handle) : false;
148	if (is_resource($handle)) {
149	@fclose($handle);
150	}
151	$originalContext = is_string($firstLine) ? json_decode($firstLine, true) : null;
152	if (is_array($originalContext)) {
153	unset($originalContext['event'], $originalContext['stage'], $originalContext['elapsed_ms']);
154	$this->appendJsonLine($path, array_merge($originalContext, array(
155	'ts' => $this->clock->nowFloat(),
156	'event' => 'abandoned_recovered',
157	'status' => 'worker-ended-without-shutdown',
158	)));
159	} else {
160	$this->reportFailure('Abandoned AJAX trace context could not be parsed: ' . $path);
161	}
162	$this->promote();
163	$this->pendingPath = $ownPending;
164	}
165	}
166
167	/**
168	* Bounded recent journal lines for the existing support-request payload,
169	* newest files last. Pending spools are included on purpose: a request
170	* that is hung RIGHT NOW has written nothing to the journal yet, and it
171	* is the most interesting request in the file.
172	*
173	* This journal holds no client verdicts of its own -- they are written to
174	* the checkpoint journal -- so a caller that omits $knownFailingIds gets an
175	* excerpt that cannot tell a browser-lost request from a healthy one. See
176	* ABJ_404_Solution_DiagnosticJournalExcerpt::failureIndex().
177	*
178	* @param array<string, bool> $knownFailingIds
179	* @param array{paths: array<int, string>, manifest: array<string, mixed>}\|null $fileSelection
180	* Shared selection plan used by the primary support manifest.
181	*/
182	public static function readRecentForSupport(
183	array $knownFailingIds = array(),
184	?array $fileSelection = null
185	): string {
186	try {
187	$directory = self::resolveSupportDirectory();
188	if ($directory === '') {
189	return '';
190	}
191	return ABJ_404_Solution_DiagnosticJournalExcerpt::compose(
192	self::supportExcerptPaths($directory),
193	self::MAX_SUPPORT_EXCERPT_BYTES,
194	"Recent AJAX stage traces (JSONL):\n",
195	$knownFailingIds,
196	null,
197	$fileSelection
198	);
199	} catch (Throwable $e) {
200	self::reportStaticFailure('AJAX trace support excerpt failed: ' . $e->getMessage());
201	return '';
202	}
203	}
204
205	/**
206	* What readRecentForSupport() will look at, whether or not any of it
207	* exists, so ABJ_404_Solution_DiagnosticCollectionManifest can state what
208	* was checked even when the answer is "nothing was there".
209	*
210	* The candidate list comes from the same private helper the reader itself
211	* uses: a manifest that described a DIFFERENT set of files than the read
212	* would be worse than no manifest at all.
213	*
214	* `writer_arming` is reported alongside, because a channel whose WRITER is
215	* opt-in has a second way to come back empty that stats of the directory
216	* cannot see. Support report 2026-08-27 (Azure App Service, plugin 4.3.4)
217	* spent the whole capture on that difference: usable directory, writable
218	* directory, zero files, and no way to learn that
219	* ABJ_404_Solution_AjaxDiagnosticRequestPolicy had never armed the writer
220	* on that site. "Nothing to record" and "recording was off" must not
221	* produce the same manifest.
222	*
223	* @return array{channel: string, directory: string, usable: bool, paths: array<int, string>,
224	* writer_arming: array<string, mixed>}
225	*/
226	public static function supportCollectionSource(): array {
227	try {
228	$directory = self::resolveSupportDirectory();
229	return array(
230	'channel' => 'ajax_stage_trace',
231	'directory' => $directory,
232	'usable' => $directory !== '',
233	'paths' => $directory === '' ? array() : self::supportExcerptPaths($directory),
234	'writer_arming' => self::writerArming(),
235	);
236	} catch (Throwable $e) {
237	self::reportStaticFailure('AJAX trace support source resolution failed: ' . $e->getMessage());
238	return array(
239	'channel' => 'ajax_stage_trace',
240	'directory' => '',
241	'usable' => false,
242	'paths' => array(),
243	'writer_arming' => self::writerArming(),
244	);
245	}
246	}
247
248	/**
249	* What the trace WRITER would do on this site right now. Never throws: a
250	* manifest that cannot describe the arming policy still has to describe the
251	* files, so an unavailable policy is reported as such rather than removing
252	* the field.
253	*
254	* @return array<string, mixed>
255	*/
256	private static function writerArming(): array {
257	if (!class_exists('ABJ_404_Solution_AjaxDiagnosticRequestPolicy')) {
258	return array('status' => 'unavailable', 'reason' => 'policy_class_unavailable');
259	}
260	try {
261	return ABJ_404_Solution_AjaxDiagnosticRequestPolicy::armingState();
262	} catch (Throwable $e) {
263	self::reportStaticFailure('AJAX trace arming state failed: ' . $e->getMessage());
264	return array('status' => 'unavailable', 'reason' => 'policy_read_failed');
265	}
266	}
267
268	/**
269	* Rotated file, current journal, then any live pending spools -- oldest
270	* first, which is the order the excerpt reader breaks mtime ties on.
271	*
272	* @param string $directory With a trailing separator.
273	* @return array<int, string>
274	*/
275	private static function supportExcerptPaths(string $directory): array {
276	$paths = array(
277	$directory . self::ROTATED_FILE,
278	$directory . self::JOURNAL_FILE,
279	);
280	$pendingPaths = glob($directory . self::PENDING_GLOB);
281	return is_array($pendingPaths) ? array_merge($paths, $pendingPaths) : $paths;
282	}
283
284	/**
285	* Existing journal and pending-spool files, for a channel that carries
286	* them WHOLE. See CheckpointJournalReader::supportArchivePaths().
287	*
288	* @return array<int, string>
289	*/
290	public static function supportArchivePaths(): array {
291	try {
292	$directory = self::resolveSupportDirectory();
293	if ($directory === '') {
294	return array();
295	}
296	$paths = array();
297	foreach (array(self::JOURNAL_FILE, self::ROTATED_FILE) as $name) {
298	if (@is_file($directory . $name)) {
299	$paths[] = $directory . $name;
300	}
301	}
302	$pendingPaths = glob($directory . self::PENDING_GLOB);
303	return is_array($pendingPaths) ? array_merge($paths, $pendingPaths) : $paths;
304	} catch (Throwable $e) {
305	self::reportStaticFailure('AJAX trace archive path resolution failed: ' . $e->getMessage());
306	return array();
307	}
308	}
309
310	/**
311	* The trace directory as the read-side callers see it, with a trailing
312	* separator, or '' when unavailable. Resolved through the same filter the
313	* writer uses so a site that relocates the directory relocates every
314	* reader with it.
315	*/
316	private static function resolveSupportDirectory(): string {
317	return ABJ_404_Solution_DiagnosticDirectoryResolver::resolve();
318	}
319
320	/** @param array<string, mixed> $record */
321	private function appendJsonLine(string $path, array $record): bool {
322	$json = json_encode($record, JSON_UNESCAPED_SLASHES);
323	if (!is_string($json)) {
324	$this->reportFailure('AJAX trace JSON encoding failed.');
325	return false;
326	}
327	// The descriptor is held for the request rather than re-opened per
328	// record, and the lock is taken on that same held descriptor. See
329	// ABJ_404_Solution_DiagnosticAppendStream: this sink is lower volume
330	// than the checkpoint journal, but it is the same shape and it shares
331	// the fix rather than keeping a second copy of the write path.
332	$acquired = ABJ_404_Solution_DiagnosticAppendStream::acquireExclusive(
333	$path,
334	self::PROMOTION_LOCK_WAIT_TIMEOUT_US
335	);
336	if ($acquired['status'] === 'failed') {
337	$this->reportFailure('AJAX trace file could not be opened: ' . $path);
338	return false;
339	}
340	if ($acquired['status'] === 'lock_timeout') {
341	$this->reportFailure('AJAX trace file lock failed: ' . $path);
342	return false;
343	}
344	try {
345	$written = ABJ_404_Solution_DiagnosticAppendStream::append($path, $json . "\n");
346	$ok = $written['status'] === 'complete';
347	if (!$ok) {
348	$this->reportFailure('AJAX trace append/flush failed: ' . $path);
349	}
350	} finally {
351	ABJ_404_Solution_DiagnosticAppendStream::release($path);
352	}
353	return $ok;
354	}
355
356	private function removePending(): void {
357	// Drop the held descriptor BEFORE unlinking: a descriptor to a deleted
358	// inode accepts writes that no reader can ever find.
359	ABJ_404_Solution_DiagnosticAppendStream::invalidate($this->pendingPath);
360	if (@is_file($this->pendingPath) && !@unlink($this->pendingPath)) {
361	$this->reportFailure('AJAX pending trace could not be removed: ' . $this->pendingPath);
362	}
363	}
364
365	/** @param resource $lock */
366	private function acquirePromotionLock($lock): bool {
367	$started = $this->monotonicNanoseconds();
368	do {
369	if (@flock($lock, LOCK_EX \| LOCK_NB)) {
370	return true;
371	}
372	if ($this->elapsedMicroseconds($started) >= self::PROMOTION_LOCK_WAIT_TIMEOUT_US) {
373	return false;
374	}
375	usleep(1000);
376	} while (true);
377	}
378
379	private function monotonicNanoseconds(): int {
380	return function_exists('hrtime')
381	? (int)hrtime(true)
382	: (int)round($this->clock->nowFloat() * 1000000000);
383	}
384
385	private function elapsedMicroseconds(int $started): int {
386	return max(0, (int)round(($this->monotonicNanoseconds() - $started) / 1000));
387	}
388
389	private function reportFailure(string $message): void {
390	if ($this->failureReported) {
391	return;
392	}
393	$this->failureReported = true;
394	self::reportStaticFailure($message);
395	}
396
397	private static function reportStaticFailure(string $message): void {
398	// Unconditional; see AjaxCheckpointLogger::reportFailure().
399	abj404_logPhpFallback('ajax-trace', $message);
400	}
401	}
402