404-solution / includes / diagnostics / TemplateFileReadTracer.php

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

258 lines 9.5 KB

Raw Download Zip

1	<?php
2
3	if (!defined('ABSPATH')) {
4	exit;
5	}
6
7	/**
8	* Durable attribution for local template-file I/O during the table AJAX path.
9	*
10	* Absolute paths and warning text never enter the checkpoint journal. A stable
11	* identifier combines the file extension with a hash of the basename, which
12	* is enough to correlate repeated reads without disclosing the installation
13	* layout. Each platform boundary writes its start before entering the call so
14	* a blocked stat, read, retry wait, warning logger, or cURL fallback remains
15	* visible in bounded support evidence.
16	*
17	* THE VOLUME IS CAPPED, and measurement is why. Template I/O is the one
18	* diagnostic family whose record count scales with the RENDERED ROW COUNT: on
19	* the owner's localhost on 2026-08-10, one part=all table AJAX request wrote
20	* 872 of its 3,135 checkpoint records here at rowsPerPage=25, and 3,212 of
21	* 5,476 at rowsPerPage=100, while every other family stayed flat. That is what
22	* turned debug_mode from a fixed surcharge into one that grows with the table,
23	* and a diagnostic a user cannot afford to switch on does not diagnose
24	* anything.
25	*
26	* Past the cap an operation is still announced on the active-operations
27	* channel, so the decisive evidence survives: a stalled read is exactly an
28	* operation that went 'active' and never went 'complete', which is how a
29	* blocked stat is recognised whether or not its journal record was written.
30	* What is lost past the cap is the per-operation elapsed_ms and byte counts of
31	* later reads, which is bounded-detail loss, not blindness.
32	*/
33	final class ABJ_404_Solution_TemplateFileReadTracer {
34
35	/**
36	* Journal records this request may spend here. Matched to the sibling
37	* tracers' budgets (DatabaseQueryFilterTracer, TableRenderTranslationTracer)
38	* so one family cannot crowd the others out of a bounded support excerpt.
39	*/
40	const MAX_RECORDS = 64;
41
42	/** @var int */
43	private static $operationSequence = 0;
44
45	/** @var int Journal records written this request. */
46	private static $recordCount = 0;
47
48	/** @var bool Whether the cap notice has been written for this request. */
49	private static $capRecorded = false;
50
51	/**
52	* Test seam: a PHPUnit worker never gets the end-of-request that would
53	* otherwise reset this budget, so one test's template reads would spend
54	* the next test's. Registered in ABJ404_RequestScopedStateReset.
55	*/
56	public static function resetForTests(): void {
57	self::$operationSequence = 0;
58	self::$recordCount = 0;
59	self::$capRecorded = false;
60	}
61
62	/**
63	* @template T
64	* @param array<string, int\|string\|bool\|null> $fields
65	* @param callable(): T $work
66	* @return T
67	*/
68	public static function trace(
69	string $operation,
70	string $path,
71	array $fields,
72	callable $work
73	) {
74	$requestId = self::requestId();
75	if ($requestId === '') {
76	return $work();
77	}
78
79	$operationId = self::operationId($requestId, $operation);
80	$identity = array_merge(array(
81	'operation_id' => $operationId,
82	'operation' => self::safeOperation($operation),
83	'template_id' => self::templateId($path),
84	), $fields);
85	// Both records of a pair are budgeted together: a start whose end
86	// cannot be afforded is what a stall looks like, so spending the last
87	// slot on one would manufacture a phantom stall in the evidence.
88	$journalled = self::$recordCount + 2 <= self::MAX_RECORDS;
89	if ($journalled) {
90	self::$recordCount++;
91	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent(
92	$requestId,
93	'template_file_operation_start',
94	$identity
95	);
96	} else {
97	self::recordCapOnce($requestId);
98	ABJ_404_Solution_AjaxCheckpointLogger::recordActiveOperation(
99	$requestId,
100	'template_file_operation',
101	'active',
102	$identity
103	);
104	}
105	$startedAt = self::nowFloat();
106	try {
107	$result = $work();
108	} catch (Throwable $error) {
109	self::writeEnd($requestId, $journalled, array_merge($identity, array(
110	'status' => 'error',
111	'elapsed_ms' => self::elapsedMilliseconds($startedAt),
112	'result' => array('error' => true),
113	'bytes' => 0,
114	'error' => self::errorSummary($error),
115	)));
116	throw $error;
117	}
118
119	$summary = self::resultSummary($operation, $result, $fields);
120	self::writeEnd($requestId, $journalled, array_merge($identity, array(
121	'status' => 'complete',
122	'elapsed_ms' => self::elapsedMilliseconds($startedAt),
123	'result' => $summary,
124	'bytes' => $summary['bytes'] ?? 0,
125	)));
126	return $result;
127	}
128
129	/**
130	* Close an operation on the channel its start was written to. Mixing them
131	* would leave an active operation that never completes, which is the exact
132	* signature of a stalled read.
133	*
134	* @param array<string, mixed> $fields
135	*/
136	private static function writeEnd(string $requestId, bool $journalled, array $fields): void {
137	if ($journalled) {
138	self::$recordCount++;
139	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent(
140	$requestId,
141	'template_file_operation_end',
142	$fields
143	);
144	return;
145	}
146	ABJ_404_Solution_AjaxCheckpointLogger::recordActiveOperation(
147	$requestId,
148	'template_file_operation',
149	'complete',
150	$fields
151	);
152	}
153
154	/** Name the cap in the journal once, so a truncated family is never silent. */
155	private static function recordCapOnce(string $requestId): void {
156	if (self::$capRecorded) {
157	return;
158	}
159	self::$capRecorded = true;
160	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent(
161	$requestId,
162	'template_file_operation_capped',
163	array(
164	'recorded' => self::$recordCount,
165	'max_records' => self::MAX_RECORDS,
166	)
167	);
168	}
169
170	private static function requestId(): string {
171	if (!class_exists('ABJ_404_Solution_AjaxDiagnosticRequestPolicy')) {
172	return '';
173	}
174	return ABJ_404_Solution_AjaxDiagnosticRequestPolicy::instrumentedRequestIdFromGlobalContext();
175	}
176
177	private static function operationId(string $requestId, string $operation): string {
178	self::$operationSequence++;
179	return substr(hash(
180	'sha256',
181	$requestId . '\|' . $operation . '\|' . self::$operationSequence
182	), 0, 12);
183	}
184
185	private static function safeOperation(string $operation): string {
186	return preg_match('/^[a-z][a-z0-9_]{0,63}$/', $operation) === 1
187	? $operation
188	: 'operation#' . substr(hash('sha256', $operation), 0, 12);
189	}
190
191	private static function templateId(string $path): string {
192	$basename = basename(str_replace('\\', '/', $path));
193	$extension = strtolower((string)pathinfo($basename, PATHINFO_EXTENSION));
194	$kind = preg_match('/^[a-z0-9]{1,12}$/', $extension) === 1
195	? $extension
196	: 'file';
197	return $kind . '#' . substr(hash('sha256', $basename), 0, 12);
198	}
199
200	/**
201	* @param mixed $result
202	* @param array<string, int\|string\|bool\|null> $fields
203	* @return array<string, int\|string\|bool\|null>
204	*/
205	private static function resultSummary(string $operation, $result, array $fields): array {
206	if ($operation === 'stat') {
207	return array('exists' => (bool)$result, 'bytes' => 0);
208	}
209	if ($operation === 'read_attempt' \|\| $operation === 'curl_fallback') {
210	return array(
211	'success' => is_string($result),
212	'bytes' => is_string($result) ? strlen($result) : 0,
213	);
214	}
215	if ($operation === 'retry_wait') {
216	return array(
217	'delay_us' => isset($fields['delay_us']) ? (int)$fields['delay_us'] : 0,
218	'bytes' => 0,
219	);
220	}
221	return array('type' => gettype($result), 'bytes' => 0);
222	}
223
224	/** @return array{class:string,code:int,message:string,message_length:int} */
225	private static function errorSummary(Throwable $error): array {
226	$message = $error->getMessage();
227	$class = get_class($error);
228	return array(
229	'class' => preg_match('/^[A-Za-z_\\\\][A-Za-z0-9_\\\\]{0,159}$/', $class) === 1
230	? $class
231	: 'class#' . substr(hash('sha256', $class), 0, 12),
232	'code' => is_int($error->getCode()) ? $error->getCode() : 0,
233	'message' => 'message#' . substr(hash('sha256', $message), 0, 12),
234	'message_length' => strlen($message),
235	);
236	}
237
238	private static function nowFloat(): ?float {
239	if (function_exists('abj_clock')) {
240	return abj_clock()->nowFloat();
241	}
242	if (class_exists('ABJ_404_Solution_SystemClock')) {
243	return (new ABJ_404_Solution_SystemClock())->nowFloat();
244	}
245	return null;
246	}
247
248	private static function elapsedMilliseconds(?float $startedAt): ?int {
249	if ($startedAt === null) {
250	return null;
251	}
252	$finishedAt = self::nowFloat();
253	return $finishedAt === null
254	? null
255	: max(0, (int)round(($finishedAt - $startedAt) * 1000));
256	}
257	}
258