404-solution / includes / diagnostics / AjaxRequestTrace.php

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

423 lines 19.7 KB

Raw Download Zip

1	<?php
2
3	if (!defined('ABSPATH')) {
4	exit;
5	}
6
7	/**
8	* Durable write-ahead journal for one admin AJAX request.
9	*
10	* Each stage -- starting with request_start, the very first flushed write --
11	* is appended and flushed to a request-local pending file before work
12	* starts. Every request is ALWAYS promoted into one bounded, rotated JSONL
13	* journal (matrix coverage req. 4): there is no fast-complete deletion, so a
14	* successful request under the retention threshold cannot silently vanish
15	* the way beta.1's trace did. Rotation is the only bound on retention.
16	* A hard worker kill can skip PHP shutdown, so stale pending files are recovered
17	* into the journal by a later request instead of losing the last started stage.
18	*
19	* This class owns the request's stages while it runs. What happens to the
20	* process AFTER the response is complete belongs to
21	* ABJ_404_Solution_AjaxTeardownRecorder, which the sentinels below delegate to.
22	*/
23	final class ABJ_404_Solution_AjaxRequestTrace implements ABJ_404_Solution_DiagnosticInternalHookObserver {
24
25	const SCHEMA_VERSION = 1;
26
27	/** @var array<string, scalar> */
28	private $context;
29	/** @var ABJ_404_Solution_Clock */
30	private $clock;
31	/** @var ABJ_404_Solution_AjaxTraceJournal Durable storage + retention for this request's records. */
32	private $journal;
33	/** @var float */
34	private $requestStartedAt;
35	/** @var float\|null */
36	private $stageStartedAt = null;
37	/** @var string */
38	private $currentStage = '';
39	/** @var array<string, scalar> */
40	private $stageMetadata = array();
41	/** @var bool */
42	private $active = true;
43	/** @var float\|null Set when finish() runs; lets the teardown recorder measure PHP-shutdown lag after the response was logically complete. */
44	private $responseEmittedAt = null;
45	/** @var ABJ_404_Solution_AjaxTeardownRecorder Owns everything after the response is complete. */
46	private $teardownRecorder;
47	/** @var ABJ_404_Solution_ShutdownCallbackTracer\|null */
48	private $shutdownCallbackTracer;
49	/**
50	* Every trace in this process whose PHP-shutdown sentinels are still
51	* armed. The shutdown queue itself already keeps each of these traces
52	* alive until process exit, so this registry adds no retention beyond
53	* what register_shutdown_function() imposes; it exists so the test
54	* harness can retire the sentinels of traces whose "request" (one
55	* PHPUnit test) has already ended.
56	* @var array<int, self>
57	*/
58	private static $tracesWithArmedSentinels = array();
59
60	/**
61	* Start tracing for an authorized AJAX request. Failure is non-fatal.
62	*
63	* @param array<string, mixed> $context
64	* @return self\|null
65	*/
66	public static function start(array $context): ?self {
67	try {
68	$directory = ABJ_404_Solution_DiagnosticDirectoryResolver::resolve($context);
69	if ($directory === '') {
70	self::reportStaticFailure('AJAX trace uploads directory is unavailable.');
71	return null;
72	}
73	if (!ABJ_404_Solution_FileSystemService::createDirectoryWithErrorMessages($directory)) {
74	self::reportStaticFailure('AJAX trace directory could not be created: ' . $directory);
75	return null;
76	}
77	$trace = new self($context, $directory, abj_clock());
78	$trace->journal->recoverAbandoned();
79	// Handler-entry and response-time sentinels preserve evidence if one
80	// shutdown mechanism is skipped. The tracer brackets WordPress's
81	// shutdown action and attributes its callbacks through shared hook
82	// instrumentation. finish() does not disarm them; PHPUnit retires
83	// them between simulated requests via disarmTeardownSentinelsForTests().
84	register_shutdown_function(array($trace, 'recordShutdown'));
85	self::$tracesWithArmedSentinels[] = $trace;
86	if (function_exists('add_action')) {
87	$trace->shutdownCallbackTracer = new ABJ_404_Solution_ShutdownCallbackTracer(
88	(string)($trace->context['request_id'] ?? ''), rtrim($directory, '/\\') . DIRECTORY_SEPARATOR
89	);
90	$trace->shutdownCallbackTracer->registerSentinels(array($trace, 'recordShutdownActionEarly'),
91	array($trace, 'recordShutdownActionLate'));
92	}
93	return $trace;
94	} catch (Throwable $e) {
95	self::reportStaticFailure('AJAX trace initialization failed: ' . $e->getMessage());
96	return null;
97	}
98	}
99
100	/**
101	* @param array<string, mixed> $context
102	*/
103	private function __construct(array $context, string $directory, ABJ_404_Solution_Clock $clock) {
104	$this->clock = $clock;
105	$this->requestStartedAt = $clock->nowFloat();
106	$this->context = $this->normalizeContext($context);
107	$stamp = str_replace('.', '', sprintf('%.6f', $this->requestStartedAt));
108	$pendingPath = $directory . 'abj404_ajax_trace_'
109	. $this->context['request_id'] . '_' . $this->context['part'] . '_'
110	. $this->context['retry_count'] . '_'
111	. ABJ_404_Solution_PhpRuntimeCapabilityAdapter::processToken()
112	. '_' . $stamp . '.pending.jsonl';
113	$this->journal = new ABJ_404_Solution_AjaxTraceJournal($directory, $pendingPath, $clock);
114	$this->teardownRecorder = new ABJ_404_Solution_AjaxTeardownRecorder(
115	$clock, $directory, $this->journal);
116
117	// request_start MUST be the first flushed write for this request: it is
118	// the evidence that the trace even started, before any stage runs. If
119	// gathering the full field set itself throws, still flush a minimal
120	// record rather than silently losing the "we got this far" signal.
121	try {
122	$this->appendRecord($this->buildRequestStartRecord($context));
123	} catch (Throwable $e) {
124	$this->appendRecord(array(
125	'event' => 'request_start',
126	'request_start_error' => substr($e->getMessage(), 0, 300),
127	));
128	}
129	}
130
131	/**
132	* The request_start record: the ledger/event fields this class owns,
133	* merged with the process/build/runtime capture that
134	* ABJ_404_Solution_RequestEnvironmentFingerprint owns.
135	*
136	* @param array<string, mixed> $rawContext
137	* @return array<string, mixed>
138	*/
139	private function buildRequestStartRecord(array $rawContext): array {
140	$clientSentAtRaw = $rawContext['client_sent_at'] ?? '';
141	$handlerClassRaw = $rawContext['handler_class'] ?? '';
142	$handlerClass = is_scalar($handlerClassRaw) && (string)$handlerClassRaw !== '' ? (string)$handlerClassRaw : null;
143	$environment = new ABJ_404_Solution_RequestEnvironmentFingerprint($this->clock);
144
145	return array_merge(array(
146	'event' => 'request_start',
147	'client_sent_at' => is_scalar($clientSentAtRaw) ? substr((string)$clientSentAtRaw, 0, 64) : '',
148	), $environment->capture($handlerClass, 'abj404_trace_probe_' . $this->context['request_id']));
149	}
150
151	/** Begin and flush a stage before its work runs. */
152	public function beginStage(string $stage): void {
153	if (!$this->active) {
154	return;
155	}
156	if ($this->currentStage !== '') {
157	$this->endStage('superseded');
158	}
159	$this->currentStage = substr($stage, 0, 128);
160	$this->stageStartedAt = $this->clock->nowFloat();
161	$this->stageMetadata = array();
162	$this->appendRecord(array('event' => 'stage_start', 'stage' => $this->currentStage));
163	}
164
165	/** @param array<string, scalar> $metadata */
166	public function addStageMetadata(array $metadata): void {
167	if (!$this->active \|\| $this->currentStage === '') {
168	return;
169	}
170	$changed = array();
171	foreach ($metadata as $key => $value) {
172	if (!is_string($key) \|\| !is_scalar($value)) {
173	continue;
174	}
175	if ($key === 'db_timeout_mode') {
176	$value = $this->strongestTimeoutMode((string)($this->stageMetadata[$key] ?? ''), (string)$value);
177	}
178	$value = is_string($value) ? substr($value, 0, 256) : $value;
179	if (array_key_exists($key, $this->stageMetadata) && $this->stageMetadata[$key] === $value) {
180	continue;
181	}
182	$this->stageMetadata[$key] = $value;
183	$changed[$key] = $value;
184	}
185	if ($changed !== array()) {
186	$startedAt = $this->stageStartedAt ?? $this->clock->nowFloat();
187	$this->appendRecord(array_merge(array(
188	'event' => 'stage_metadata',
189	'stage' => $this->currentStage,
190	'elapsed_ms' => max(0, (int)round(($this->clock->nowFloat() - $startedAt) * 1000)),
191	), $changed));
192	}
193	}
194
195	public function endStage(string $status = 'complete'): void {
196	if (!$this->active \|\| $this->currentStage === '') {
197	return;
198	}
199	$startedAt = $this->stageStartedAt ?? $this->clock->nowFloat();
200	$record = array_merge(array(
201	'event' => 'stage_end',
202	'stage' => $this->currentStage,
203	'status' => substr($status, 0, 32),
204	'elapsed_ms' => max(0, (int)round(($this->clock->nowFloat() - $startedAt) * 1000)),
205	), $this->stageMetadata);
206	$this->appendRecord($record);
207	$this->currentStage = '';
208	$this->stageStartedAt = null;
209	$this->stageMetadata = array();
210	}
211
212	/**
213	* Complete the request. Promotion uses the journal's bounded try-lock;
214	* on contention the support-readable pending spool stays intact for a
215	* shutdown retry after detachment. Arms a response-time-anchored teardown
216	* sentinel; see recordShutdownAtResponseTime().
217	*/
218	public function finish(string $status): void {
219	if (!$this->active) {
220	return;
221	}
222	if ($this->currentStage !== '') {
223	$this->endStage($status === 'complete' ? 'complete' : 'error');
224	}
225	$now = $this->clock->nowFloat();
226	$elapsedMs = max(0, (int)round(($now - $this->requestStartedAt) * 1000));
227	$this->responseEmittedAt = $now;
228	$this->appendRecord(array(
229	'event' => 'request_end',
230	'status' => substr($status, 0, 32),
231	'elapsed_ms' => $elapsedMs,
232	'peak_memory_bytes' => memory_get_peak_usage(true),
233	'connection_aborted' => function_exists('connection_aborted') ? connection_aborted() : 0,
234	));
235	if ($this->shutdownCallbackTracer !== null) {
236	$this->shutdownCallbackTracer->arm();
237	}
238	$this->active = false;
239	$this->journal->promote();
240	register_shutdown_function(array($this, 'recordShutdownAtResponseTime'));
241	}
242
243	/**
244	* Handler-entry teardown sentinel, armed once in start(). Beta.1's
245	* defect: this no-op'd once finish() had run (`if (!$this->active)
246	* return;`), so a slow sibling shutdown hook or a lingering
247	* client-abort that stalled the worker AFTER the response was handed
248	* off produced zero evidence -- exactly the gap that made beta.1's
249	* trace come back empty. It always writes now; already_finished and
250	* elapsed_since_response_emitted_ms tell a reader whether shutdown ran
251	* promptly after finish() or something held the process open (cause G
252	* in the timeout matrix).
253	*/
254	public function recordShutdown(): void {
255	$this->recordTeardown('shutdown',
256	ABJ_404_Solution_AjaxTeardownRecorder::MECHANISM_SHUTDOWN_FUNCTION,
257	ABJ_404_Solution_AjaxTeardownRecorder::ARMED_HANDLER_ENTRY);
258	}
259
260	/** Response-time teardown sentinel; armed a second time in finish(). */
261	public function recordShutdownAtResponseTime(): void {
262	$this->recordTeardown('shutdown_response_time',
263	ABJ_404_Solution_AjaxTeardownRecorder::MECHANISM_SHUTDOWN_FUNCTION,
264	ABJ_404_Solution_AjaxTeardownRecorder::ARMED_RESPONSE_TIME);
265	}
266
267	/**
268	* WP 'shutdown' action at PHP_INT_MIN: the earliest possible read on
269	* shutdown-time state, before any other plugin's own shutdown hook has
270	* had a chance to run. Opens the WordPress-shutdown-action bracket; see
271	* ABJ_404_Solution_ShutdownTeardownBracket.
272	*/
273	public function recordShutdownActionEarly(): void {
274	// The earliest point at which post-detach work begins. A census row
275	// still reading this phase minutes later is a worker holding its
276	// process slot while owing the browser nothing -- the shape report 193
277	// showed four times over, and a different failure from one stranded
278	// before the response was delivered.
279	ABJ_404_Solution_SameSiteRequestCensus::markPhase(
280	ABJ_404_Solution_SameSiteRequestCensus::PHASE_SHUTDOWN);
281	ABJ_404_Solution_AjaxStageDiagnostics::recordRequestPhase((string)($this->context['request_id'] ?? ''), 'wordpress_shutdown');
282	$this->teardownRecorder->noteWpActionStart($this->clock->nowFloat());
283	$this->recordTeardown('shutdown_action_min',
284	ABJ_404_Solution_AjaxTeardownRecorder::MECHANISM_WP_ACTION,
285	ABJ_404_Solution_AjaxTeardownRecorder::ARMED_HANDLER_ENTRY);
286	}
287
288	/**
289	* WP 'shutdown' action at PHP_INT_MAX: fires after every other plugin's
290	* default-priority shutdown hook has already run, so it can catch delay
291	* or damage they caused that recordShutdownActionEarly could not see.
292	* Closes the WordPress-shutdown-action bracket.
293	*/
294	public function recordShutdownActionLate(): void {
295	$this->teardownRecorder->noteWpActionEnd($this->clock->nowFloat());
296	$this->recordTeardown('shutdown_action_max',
297	ABJ_404_Solution_AjaxTeardownRecorder::MECHANISM_WP_ACTION,
298	ABJ_404_Solution_AjaxTeardownRecorder::ARMED_HANDLER_ENTRY);
299	ABJ_404_Solution_AjaxStageDiagnostics::recordRequestPhase((string)($this->context['request_id'] ?? ''), 'wordpress_shutdown', 'complete');
300	}
301
302	/**
303	* Test-harness end-of-request: mark every armed teardown sentinel in this
304	* process inert.
305	*
306	* In production a trace and its shutdown sentinels live exactly as long
307	* as one request, and the trace directory outlives them both, so the
308	* sentinels are deliberately NEVER disarmed there (see recordShutdown()
309	* for the beta.1 defect that rule replaced) and nothing in production
310	* calls this. A PHPUnit worker breaks the premise the sentinels rely on:
311	* it replays hundreds of requests in one process, each against a
312	* per-test temp directory that tearDown deletes, while
313	* register_shutdown_function() keeps every test's trace queued until the
314	* whole process exits. Without this seam each of those traces flushes
315	* into its deleted directory at process exit and reports 'AJAX trace
316	* file could not be opened' to stderr -- noise that buries real
317	* trace-write failures. Wired into ABJ404_RequestScopedStateReset next
318	* to the request-context resets that exist for the same reason.
319	*
320	* @return void
321	*/
322	public static function disarmTeardownSentinelsForTests(): void {
323	foreach (self::$tracesWithArmedSentinels as $trace) {
324	$trace->teardownRecorder->disarm();
325	}
326	self::$tracesWithArmedSentinels = array();
327	}
328
329	/**
330	* Hand this request's state to the teardown recorder and retire the trace
331	* if it wrote.
332	*
333	* The trace stays active when the write did not happen, which is what lets
334	* a later sentinel try again: a retired recorder and a failed write are
335	* both cases where nothing was recorded, and marking the request torn down
336	* on either would discard the one remaining chance to record it.
337	*
338	* @param string $mechanism One of ABJ_404_Solution_AjaxTeardownRecorder's
339	* MECHANISM_* constants.
340	* @param string $armedAt One of its ARMED_* constants.
341	*/
342	private function recordTeardown(string $event, string $mechanism, string $armedAt): void {
343	if ($this->teardownRecorder->record($event, $mechanism, $armedAt, array(
344	'envelope' => $this->baseRecord(),
345	'request_started_at' => $this->requestStartedAt,
346	'response_emitted_at' => $this->responseEmittedAt,
347	'already_finished' => !$this->active,
348	'current_stage' => $this->currentStage,
349	))) {
350	$this->active = false;
351	}
352	}
353
354	/**
355	* Wrap a record in this request's envelope (schema version, timestamp,
356	* ledger context) and hand it to durable storage. Deciding what the
357	* envelope contains is the trace's job; writing it durably is not.
358	*
359	* @param array<string, mixed> $record
360	*/
361	private function appendRecord(array $record): void {
362	$this->journal->append(array_merge($this->baseRecord(), $record));
363	}
364
365	/** @return array<string, scalar> */
366	private function baseRecord(): array {
367	return array_merge(array(
368	'schema_version' => self::SCHEMA_VERSION,
369	'ts' => $this->clock->nowFloat(),
370	), $this->context);
371	}
372
373	/**
374	* @param array<string, mixed> $context
375	* @return array{request_id: string, plugin_version: string, action: string, subpage: string, part: string, retry_count: int}
376	*/
377	private function normalizeContext(array $context): array {
378	$part = self::readScalarString($context, 'part', 'all');
379	$retryCountRaw = $context['retry_count'] ?? 0;
380	$retryCount = is_numeric($retryCountRaw) ? (int)$retryCountRaw : 0;
381	return array(
382	// Immutable request ledger (matrix coverage req. 1): the trace journal
383	// is one of the channels a request ID must be recoverable from; the
384	// others are the POST body / query string, the X-ABJ404-Request-ID
385	// request/response headers, and error payloads (Ajax_GetPaginationLinks
386	// + AjaxAdminEndpointSupport). session_id and retry_parent_id ride
387	// along so a retried request can be joined back to its parent attempt.
388	'request_id' => self::readIdField($context, 'request_id', 'unknown00'),
389	'plugin_version' => defined('ABJ404_VERSION') ? (string)ABJ404_VERSION : 'unknown',
390	'action' => substr(self::readScalarString($context, 'action'), 0, 64),
391	'subpage' => substr(self::readScalarString($context, 'subpage'), 0, 64),
392	'part' => substr($part, 0, 32),
393	'retry_count' => max(0, min(2, $retryCount)),
394	'session_id' => substr(self::readScalarString($context, 'session_id'), 0, 64),
395	'retry_parent_id' => self::readIdField($context, 'retry_parent_id', ''),
396	'header_request_id' => self::readIdField($context, 'header_request_id', ''),
397	'cf_ray' => substr(self::readScalarString($context, 'cf_ray'), 0, 64),
398	);
399	}
400
401	/** @param array<string, mixed> $context */
402	private static function readScalarString(array $context, string $key, string $default = ''): string {
403	$raw = $context[$key] ?? $default;
404	return is_scalar($raw) ? (string)$raw : $default;
405	}
406
407	/** @param array<string, mixed> $context */
408	private static function readIdField(array $context, string $key, string $fallback): string {
409	$candidate = self::readScalarString($context, $key);
410	return preg_match('/^[A-Za-z0-9]{8,64}$/', $candidate) === 1 ? $candidate : $fallback;
411	}
412
413	private function strongestTimeoutMode(string $current, string $incoming): string {
414	$rank = array('' => 0, 'none' => 1, 'wrapped' => 2, 'unwrapped' => 3);
415	return ($rank[$incoming] ?? 0) >= ($rank[$current] ?? 0) ? $incoming : $current;
416	}
417
418	private static function reportStaticFailure(string $message): void {
419	// Unconditional; see AjaxCheckpointLogger::reportFailure().
420	abj404_logPhpFallback('ajax-trace', $message);
421	}
422	}
423