404-solution / includes / diagnostics / AjaxCheckpointLogger.php

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

444 lines 18.9 KB

Raw Download Zip

1	<?php
2
3	if (!defined('ABSPATH')) {
4	exit;
5	}
6
7	/**
8	* Independent, minimal JSONL append-only logger for AJAX request checkpoints.
9	*
10	* Deliberately separate from ABJ_404_Solution_AjaxRequestTrace: every normal
11	* record opens, locks, appends, flushes, unlocks, and closes immediately. A
12	* minimal intent lands first through ABJ_404_Solution_CheckpointIntentStore's
13	* fixed system-temp sink, before uploads resolution can block. There is no
14	* pending/promotion state machine or in-memory batching, so a bug in the trace
15	* class under test cannot erase this evidence.
16	*
17	* Every public method is failure-safe: it never lets an internal write
18	* failure escape as an exception. around() re-throws only the wrapped
19	* work's own exception, never a logging failure.
20	*
21	* This class is the journal's WRITER only. The read side -- the bounded
22	* support excerpt, the collection-manifest source, and the whole-file
23	* archive paths -- lives in ABJ_404_Solution_CheckpointJournalReader, which
24	* depends on this class's directory resolution; nothing here ever calls it.
25	*/
26	final class ABJ_404_Solution_AjaxCheckpointLogger {
27
28	/**
29	* Compiled release marker. DiagnosticModuleManifestTest recomputes it
30	* from canonical source and prevents a covered code change from shipping
31	* with an old marker.
32	*/
33	const DIAGNOSTIC_BUILD_ID = '1675af0a29435f25cc1afbaef80703108620b1f8';
34
35	const CHECKPOINT_FILE = ABJ_404_Solution_CheckpointJournalWriter::CHECKPOINT_FILE;
36	const ROTATED_FILE = ABJ_404_Solution_CheckpointJournalWriter::ROTATED_FILE;
37	const LOCK_FILE = ABJ_404_Solution_CheckpointJournalWriter::LOCK_FILE;
38	const MAX_CHECKPOINT_BYTES = ABJ_404_Solution_CheckpointJournalWriter::MAX_CHECKPOINT_BYTES;
39
40	/** @var array<string, mixed>\|null */
41	private static $previousWriteTelemetry = null;
42
43	/** @var int */
44	private static $checkpointSequence = 0;
45
46	/**
47	* Nesting depth for checkpoint persistence itself.
48	*
49	* Render-scope hook instrumentation uses this to avoid treating the
50	* logger's own path-resolution filters as application render work. Without
51	* the guard, every checkpoint can recursively install another set of hook
52	* instrumentation records and exhaust the bounded evidence channel.
53	*
54	* @var int
55	*/
56	private static $recordingDepth = 0;
57
58	/**
59	* 1: full getrusage() array on every record.
60	* 2: the diagnostic subset of it (see envelope()), which halves the cost
61	* of a record and therefore doubles how much of a failing session fits
62	* inside the support payload.
63	* 3: host-pressure probes plus the preceding checkpoint write's own cost.
64	* 4: a second record kind (see recordFrequent()) for the intra-stage
65	* per-query and per-row-batch channels, and an explicit `envelope`
66	* field on every record so which kind it is never has to be inferred.
67	* 5: pre-enrichment intent records and whole-call phase telemetry, so the
68	* recorder cannot charge its own probes to the operation under test or
69	* disappear without evidence when enrichment itself stalls.
70	* 6: intents move to the independent system-temp sink before uploads
71	* resolution/filtering/creation, and frequent records gain exact
72	* intent correlation.
73	* 7: foreign operations carry complete privacy-safe identity through a
74	* fixed-sink intent, the ordinary sink, and an armed/complete state.
75	*/
76	const SCHEMA_VERSION = ABJ_404_Solution_CheckpointRecordFactory::SCHEMA_VERSION;
77
78	/** A boundary record: the full environment sample described by envelope(). */
79	const ENVELOPE_FULL = ABJ_404_Solution_CheckpointRecordFactory::ENVELOPE_FULL;
80
81	/**
82	* A high-frequency record: identity and timing only. Named on the record
83	* rather than left to inference, so a missing `rusage` reads as "this kind
84	* of record does not carry one" and never as "getrusage() was unavailable".
85	*/
86	const ENVELOPE_FREQUENT = ABJ_404_Solution_CheckpointRecordFactory::ENVELOPE_FREQUENT;
87
88	/** A minimal record written before full-envelope enrichment begins. */
89	const ENVELOPE_INTENT = ABJ_404_Solution_CheckpointRecordFactory::ENVELOPE_INTENT;
90
91	/**
92	* Resolve the same directory ABJ_404_Solution_AjaxRequestTrace uses, via
93	* the same filter, so checkpoints and the trace journal live side by
94	* side and share one support-payload excerpt. The resolution itself lives
95	* in ABJ_404_Solution_DiagnosticDirectoryResolver -- a leaf with no
96	* dependencies of its own, so a bug in the trace class still cannot take
97	* this channel down, and one request cannot pay for the same two filter
98	* dispatches thousands of times.
99	*
100	* @return string Empty string when unavailable.
101	*/
102	public static function resolveDirectory(): string {
103	try {
104	$directory = self::resolveDirectoryPath();
105	if ($directory === '') {
106	return '';
107	}
108	if (!class_exists('ABJ_404_Solution_FileSystemService')
109	\|\| !ABJ_404_Solution_FileSystemService::createDirectoryWithErrorMessages($directory)) {
110	return '';
111	}
112	return $directory;
113	} catch (Throwable $e) {
114	self::reportFailure('AJAX checkpoint directory resolution failed: ' . $e->getMessage());
115	return '';
116	}
117	}
118
119	/**
120	* The path this channel resolves to BEFORE the usability check, with a
121	* trailing separator, or '' when even the uploads directory is unknown.
122	*
123	* Split out of resolveDirectory() so a directory that could not be created
124	* is still NAMEABLE in the support-collection manifest. Collapsing an
125	* unusable path to '' is what made "the collector resolved somewhere it
126	* cannot write" indistinguishable from "there was nothing to read".
127	* Public for exactly that consumer:
128	* ABJ_404_Solution_CheckpointJournalReader::supportCollectionSource().
129	*/
130	public static function resolveDirectoryPath(): string {
131	return ABJ_404_Solution_DiagnosticDirectoryResolver::resolve();
132	}
133
134	/**
135	* Append one checkpoint record. Never throws.
136	*
137	* @param array<string, mixed> $fields
138	*/
139	public static function record(string $requestId, string $event, array $fields = array()): void {
140	if ($requestId === '') {
141	return;
142	}
143	self::$recordingDepth++;
144	try {
145	$callStartedNs = self::monotonicNanoseconds();
146	$checkpointId = self::checkpointId($callStartedNs);
147	$intentWrite = self::appendIntent($requestId, $event, $checkpointId);
148	$phaseStartedNs = self::monotonicNanoseconds();
149	$directory = self::resolveDirectoryPath();
150	ABJ_404_Solution_AjaxFrequentCheckpointWriter::rememberResolvedDirectory(
151	$requestId,
152	$directory
153	);
154	$phases = array(
155	'intent_append' => self::nonNegativeInt($intentWrite['elapsed_us'] ?? null),
156	'directory_resolve' => self::elapsedMicroseconds($phaseStartedNs),
157	);
158	if ($directory === '') {
159	return;
160	}
161	$phaseStartedNs = self::monotonicNanoseconds();
162	if (!class_exists('ABJ_404_Solution_FileSystemService')
163	\|\| !ABJ_404_Solution_FileSystemService::createDirectoryWithErrorMessages($directory)) {
164	return;
165	}
166	$phases['directory_create'] = self::elapsedMicroseconds($phaseStartedNs);
167
168	$phaseStartedNs = self::monotonicNanoseconds();
169	$hostPressure = class_exists('ABJ_404_Solution_HostPressureSampler')
170	? ABJ_404_Solution_HostPressureSampler::capture($requestId)
171	: array('status' => 'unavailable', 'reason' => 'sampler_class_unavailable');
172	$phases['host_pressure_probe'] = self::elapsedMicroseconds($phaseStartedNs);
173
174	$phaseStartedNs = self::monotonicNanoseconds();
175	$record = array_merge(
176	$fields,
177	ABJ_404_Solution_CheckpointRecordFactory::full(array(
178	'ts' => self::nowFloat(),
179	'hrtime_ns' => function_exists('hrtime') ? (int)hrtime(true) : null,
180	'host_pressure' => $hostPressure,
181	'previous_checkpoint_write' => self::previousWriteTelemetry($requestId),
182	'request_id' => $requestId,
183	'event' => $event,
184	'checkpoint_id' => $checkpointId,
185	'pid' => ABJ_404_Solution_PhpRuntimeCapabilityAdapter::processId(),
186	))
187	);
188	$phases['envelope_build'] = self::elapsedMicroseconds($phaseStartedNs);
189
190	$writeTelemetry = ABJ_404_Solution_CheckpointJournalWriter::append($directory, $record);
191	$phases['append'] = self::nonNegativeInt($writeTelemetry['elapsed_us'] ?? null);
192	self::$previousWriteTelemetry =
193	ABJ_404_Solution_CheckpointRecordFactory::completedWriteTelemetry(array(
194	'write' => $writeTelemetry,
195	'intent' => $intentWrite,
196	'request_id' => $requestId,
197	'event' => $event,
198	'checkpoint_id' => $checkpointId,
199	'total_us' => self::elapsedMicroseconds($callStartedNs),
200	'phases_us' => $phases,
201	));
202	} catch (Throwable $e) {
203	self::reportFailure('AJAX checkpoint record failed: ' . $e->getMessage());
204	} finally {
205	self::$recordingDepth = max(0, self::$recordingDepth - 1);
206	}
207	}
208
209	/**
210	* Append one HIGH-FREQUENCY checkpoint record. Never throws.
211	*
212	* The intra-stage channels (per-query attribution, row-loop progress) emit
213	* tens of records per request where the boundary channel emits one, so
214	* they cannot afford the boundary envelope. Every full record samples
215	* getrusage() AND ABJ_404_Solution_HostPressureSampler, which reads procfs
216	* and the process environment. The sampler request-caches its expensive
217	* same-UID process walk, but paying even the remaining probes per query
218	* would add measurable syscall load to the path being measured. That is
219	* the observer-effect gap G2 raised about the recorder.
220	* It would also add
221	* several hundred bytes per record to a support excerpt that is already
222	* the scarce resource.
223	*
224	* What is kept is what a stall is actually read from: the two clocks, the
225	* request ID that joins the record to everything else, the event name, and
226	* the PID. Host pressure is still sampled ~27 times across the same
227	* request by the boundary records these sit between.
228	*
229	* @param array<string, mixed> $fields
230	*/
231	public static function recordFrequent(string $requestId, string $event, array $fields = array()): void {
232	if ($requestId === '') {
233	return;
234	}
235	self::$recordingDepth++;
236	try {
237	$checkpointId = self::checkpointId(self::monotonicNanoseconds());
238	self::appendIntent($requestId, $event, $checkpointId);
239	$directory = self::resolveDirectoryPath();
240	ABJ_404_Solution_AjaxFrequentCheckpointWriter::rememberResolvedDirectory(
241	$requestId,
242	$directory
243	);
244	ABJ_404_Solution_AjaxFrequentCheckpointWriter::append(
245	$requestId,
246	$event,
247	$fields,
248	$directory,
249	false,
250	$checkpointId
251	);
252	} catch (Throwable $e) {
253	self::reportFailure('AJAX frequent checkpoint record failed: ' . $e->getMessage());
254	} finally {
255	self::$recordingDepth = max(0, self::$recordingDepth - 1);
256	}
257	}
258
259	/** True while this logger is persisting one of its own records. */
260	public static function isRecording(): bool {
261	return self::$recordingDepth > 0;
262	}
263
264	/**
265	* Replace one fixed-size post-cap operation state. Never throws.
266	*
267	* The independent intent lands before directory filtering, creation, or
268	* active-state file work. A recorder stall therefore remains distinct
269	* from the late query/callback/cache operation this state identifies.
270	* The active record reuses the intent's checkpoint ID so support
271	* compaction removes only the exact intent that reached its durable end.
272	*
273	* The allowlist is the privacy boundary. Callers cannot accidentally put
274	* SQL, URLs, cache values, or callback arguments into this file because
275	* only the redacted identity fields below cross it.
276	*
277	* @param array<string, mixed> $fields
278	*/
279	public static function recordActiveOperation(
280	string $requestId,
281	string $boundary,
282	string $state,
283	array $fields
284	): void {
285	if ($requestId === '') {
286	return;
287	}
288	ABJ_404_Solution_DurableOperationRecorder::recordActiveOperation(
289	$requestId,
290	$boundary,
291	$state,
292	$fields
293	);
294	}
295
296	/**
297	* Record a checkpoint pair (`${label}_start` / `${label}_end`) around a
298	* unit of work and return its result. The end record always fires (a
299	* finally block), and always carries elapsed_ms and status; the work's
300	* own exception (if any) propagates to the caller unchanged. elapsed_ms
301	* is null only when this process has no clock at all (see nowFloat()),
302	* which is a different finding from a stage that took no measurable time.
303	*
304	* @template T
305	* @param callable():T $work
306	* @param array<string, mixed> $startFields
307	* @param array<string, mixed>\|null $endFields Fields populated by $work for the end record.
308	* @return T
309	*/
310	public static function around(
311	string $requestId,
312	string $label,
313	callable $work,
314	array $startFields = array(),
315	?array &$endFields = null
316	) {
317	if ($requestId === '') {
318	return $work();
319	}
320	self::record($requestId, $label . '_start', $startFields);
321	$startedAt = self::nowFloat();
322	$status = 'complete';
323	try {
324	return $work();
325	} catch (Throwable $e) {
326	$status = 'error';
327	throw $e;
328	} finally {
329	self::record($requestId, $label . '_end', array_merge($endFields ?? array(), array(
330	'status' => $status,
331	'elapsed_ms' => self::elapsedMs($startedAt),
332	)));
333	}
334	}
335
336	/** @return array<string, mixed> */
337	private static function previousWriteTelemetry(string $requestId): array {
338	$previous = self::$previousWriteTelemetry;
339	if (!is_array($previous) \|\| ($previous['request_id'] ?? '') !== $requestId) {
340	return array('status' => 'unavailable', 'reason' => 'no_previous_write');
341	}
342	return $previous;
343	}
344
345	/** @return array<string, mixed> */
346	private static function appendIntent(
347	string $requestId,
348	string $event,
349	string $checkpointId
350	): array {
351	return ABJ_404_Solution_CheckpointIntentStore::append(
352	ABJ_404_Solution_CheckpointRecordFactory::intent(array(
353	'request_id' => $requestId,
354	'event' => $event,
355	'checkpoint_id' => $checkpointId,
356	'hrtime_ns' => function_exists('hrtime') ? (int)hrtime(true) : null,
357	'pid' => ABJ_404_Solution_PhpRuntimeCapabilityAdapter::processId(),
358	))
359	);
360	}
361
362	private static function checkpointId(int $startedNs): string {
363	self::$checkpointSequence++;
364	return self::alphabeticHex(
365	ABJ_404_Solution_PhpRuntimeCapabilityAdapter::processNumericToken()
366	) . '-'
367	. self::alphabeticHex($startedNs) . '-'
368	. self::alphabeticHex(self::$checkpointSequence);
369	}
370
371	/**
372	* Hex-shaped compactness without decimal substrings that can impersonate
373	* a redacted numeric URL/id in diagnostic leak checks.
374	*/
375	private static function alphabeticHex(int $value): string {
376	return strtr(dechex($value), '0123456789abcdef', 'ghijklmnopqrstuv');
377	}
378
379	/** @param mixed $value */
380	private static function nonNegativeInt($value): int {
381	return is_numeric($value) ? max(0, (int)$value) : 0;
382	}
383
384	private static function monotonicNanoseconds(): int {
385	return function_exists('hrtime') ? (int)hrtime(true) : 0;
386	}
387
388	private static function elapsedMicroseconds(int $startedNs): int {
389	return max(0, (int)round((self::monotonicNanoseconds() - $startedNs) / 1000));
390	}
391
392	/**
393	* Seconds as a float from the clock seam, or null when this process has
394	* no clock at all. Three states, because this logger runs in all three:
395	*
396	* 1. Container up: abj_clock(), so FrozenClock drives it in tests.
397	* 2. Boot window: 404-solution.php records `boot_plugin_entry` right
398	* after spl_autoload_register(), long before Loader.php requires
399	* service-locator.php. SystemClock is what abj_clock() would return
400	* there anyway, so this is the same reading, not a second source.
401	* 3. Neither: a corrupt plugin directory (the safe autoloader returns
402	* SILENTLY for a missing class) or the response-tail subprocess
403	* probe, whose file set has no clock in it. Constructing SystemClock
404	* fatals there, and a logger built to keep recording while the rest
405	* of the stack is broken must not be what kills the request. Null
406	* instead, so an absent `ts` reads as "no clock was reachable"
407	* rather than as a fabricated timestamp; hrtime_ns, pid and the
408	* request id still identify the record.
409	*
410	* Mirrors ABJ_404_Solution_SameSiteRequestCensus::nowFloat(), and is
411	* deliberately inline rather than a shared helper class: such a class
412	* would be one more file that has to exist for state 3 to work.
413	*/
414	/**
415	* Milliseconds since $startedAt, or null when either end of the interval
416	* had no clock to read. Never a number derived from only one reading.
417	*/
418	private static function elapsedMs(?float $startedAt): ?int {
419	if ($startedAt === null) {
420	return null;
421	}
422	$now = self::nowFloat();
423	return $now === null ? null : max(0, (int)round(($now - $startedAt) * 1000));
424	}
425
426	private static function nowFloat(): ?float {
427	if (function_exists('abj_clock')) {
428	return abj_clock()->nowFloat();
429	}
430	if (class_exists('ABJ_404_Solution_SystemClock')) {
431	return (new ABJ_404_Solution_SystemClock())->nowFloat();
432	}
433	return null;
434	}
435
436	private static function reportFailure(string $message): void {
437	// Unconditional: abj404_logPhpFallback() is defined at plugin entry
438	// (404-solution.php), before any class here can be autoloaded, so a raw
439	// error_log() second sink was unreachable and made this file an
440	// offender in the centralized-error-log audit.
441	abj404_logPhpFallback('ajax-checkpoint', $message);
442	}
443	}
444