404-solution / includes / diagnostics / CheckpointJournalWriter.php

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

241 lines 11.2 KB

Raw Download Zip

1	<?php
2
3	if (!defined('ABSPATH')) {
4	exit;
5	}
6
7	/**
8	* Persists one checkpoint record with bounded lock acquisition.
9	*
10	* A held filesystem lock must never manufacture the timeout this diagnostic
11	* is measuring. Normal writes remain serialized for rotation safety; when
12	* the advisory lock exceeds its deadline, one O_APPEND emergency record is
13	* written without taking that same lock and the caller resumes immediately.
14	*/
15	final class ABJ_404_Solution_CheckpointJournalWriter {
16
17	const CHECKPOINT_FILE = 'abj404_ajax_checkpoints.jsonl';
18	const ROTATED_FILE = 'abj404_ajax_checkpoints.old.jsonl';
19	const LOCK_FILE = 'abj404_ajax_checkpoints.lock';
20	/**
21	* One current plus one rotated file retain a measured worst-case session.
22	*
23	* Sized against the measurement, not chosen for tidiness, and raised once
24	* per schema that adds per-record volume -- because the failure mode of an
25	* undersized cap is not "less detail", it is rotation DELETING the first
26	* failures of a session before support extraction can ever rank them.
27	* Schema 3 added host pressure and recorder cost and forced the move from
28	* 512 KB to 1 MB. Schema 4 adds the intra-stage per-query and per-row
29	* channels, which take a table request from 26-27 records (~13-16 KB) to
30	* ~59 records (~30 KB); the worst-case session this project calibrates
31	* against -- six failing attempts, the seven-step canary ladder, and sixty
32	* detect-only polls, 69 requests in all -- measures 2,096,927 bytes, so a
33	* 1 MB cap rotated twice and deleted every one of the six failures.
34	*
35	* Retention worst case is ONE cap's worth (immediately after a rotation
36	* the current file is empty), so the cap itself, not cap*2, is what has to
37	* exceed a whole session. 4 MB leaves roughly 1.9x headroom over the
38	* measured one. SupportEvidenceWorstCaseVolumeTest is that measurement
39	* turned into a gate, and it fails if this drifts back under it.
40	*/
41	const MAX_CHECKPOINT_BYTES = 4194304;
42	const LOCK_WAIT_TIMEOUT_US = 50000;
43
44	/**
45	* @param array<string, mixed> $record
46	* @return array<string, mixed> Measured write result for the next record.
47	*/
48	public static function append(string $directory, array $record): array {
49	$startedNs = self::monotonicNanoseconds();
50	$event = is_string($record['event'] ?? null) ? $record['event'] : 'unknown';
51	$requestId = is_string($record['request_id'] ?? null) ? $record['request_id'] : 'unknown00';
52	$path = $directory . self::CHECKPOINT_FILE;
53	$json = json_encode($record, JSON_UNESCAPED_SLASHES);
54	if (!is_string($json)) {
55	self::reportFailure('AJAX checkpoint JSON encoding failed.');
56	return self::result(array('status' => 'failed', 'reason' => 'json_encode_failed',
57	'request_id' => $requestId, 'event' => $event, 'started_ns' => $startedNs));
58	}
59
60	$lockPath = $directory . self::LOCK_FILE;
61	$acquired = ABJ_404_Solution_DiagnosticAppendStream::acquireExclusive(
62	$lockPath,
63	self::LOCK_WAIT_TIMEOUT_US
64	);
65	if ($acquired['status'] === 'failed') {
66	self::reportFailure('AJAX checkpoint lock file could not be opened: ' . $lockPath);
67	return self::result(array('status' => 'failed', 'reason' => 'lock_open_failed',
68	'request_id' => $requestId, 'event' => $event, 'started_ns' => $startedNs));
69	}
70	$status = 'complete';
71	$reason = '';
72	try {
73	if ($acquired['status'] === 'lock_timeout') {
74	$status = 'lock_timeout';
75	$reason = 'lock_wait_exceeded';
76	$waitUs = self::elapsedMicroseconds($startedNs);
77	self::appendLockTimeoutRecord(array(
78	'path' => $path,
79	'record' => $record,
80	'blocked_event' => $event,
81	'wait_us' => $waitUs,
82	));
83	self::reportFailure('AJAX checkpoint lock timed out after ' . $waitUs . 'us: ' . $path);
84	return self::result(array('status' => $status, 'reason' => $reason,
85	'request_id' => $requestId, 'event' => $event, 'started_ns' => $startedNs));
86	}
87	$outcome = self::appendUnderLock(array(
88	'directory' => $directory,
89	'path' => $path,
90	'line' => $json . "\n",
91	));
92	$status = $outcome['status'];
93	$reason = $outcome['reason'];
94	} finally {
95	$released = ABJ_404_Solution_DiagnosticAppendStream::release($lockPath);
96	if ($released['status'] === 'failed') {
97	$status = 'failed';
98	$reason = 'unlock_failed';
99	self::reportFailure('AJAX checkpoint lock could not be released: ' . $path);
100	}
101	}
102	return self::result(array('status' => $status, 'reason' => $reason,
103	'request_id' => $requestId, 'event' => $event, 'started_ns' => $startedNs));
104	}
105
106	/**
107	* @param array{directory: string, path: string, line: string} $write
108	* @return array{status: string, reason: string}
109	*/
110	private static function appendUnderLock(array $write): array {
111	$directory = $write['directory'];
112	$path = $write['path'];
113	$line = $write['line'];
114	$status = 'complete';
115	$reason = '';
116	// The size comes from the request-scoped descriptor rather than a
117	// filesize() per record: one stat at open, re-seeded whenever the
118	// descriptor is revalidated. See ABJ_404_Solution_DiagnosticAppendStream.
119	$size = ABJ_404_Solution_DiagnosticAppendStream::sizeOf($path);
120	if (($size + strlen($line)) > self::MAX_CHECKPOINT_BYTES) {
121	// A sibling may have rotated the held descriptor away from this
122	// path. Revalidate before a destructive decision: its stale size
123	// must not delete the retained generation and rotate a small live
124	// journal merely because the old inode was near the cap.
125	$size = ABJ_404_Solution_DiagnosticAppendStream::revalidatedSizeOf($path);
126	}
127	if (($size + strlen($line)) > self::MAX_CHECKPOINT_BYTES) {
128	$old = $directory . self::ROTATED_FILE;
129	if (@is_file($old) && !@unlink($old)) {
130	$status = 'failed';
131	$reason = 'rotated_file_delete_failed';
132	self::reportFailure('AJAX checkpoint rotated file could not be deleted: ' . $old);
133	}
134	if (@is_file($path) && !@rename($path, $old)) {
135	$status = 'failed';
136	$reason = 'rotation_rename_failed';
137	self::reportFailure('AJAX checkpoint file could not be rotated: ' . $path);
138	}
139	// The held descriptor now names the rotated file, so drop it: the
140	// record that triggered the rotation belongs in the new journal.
141	ABJ_404_Solution_DiagnosticAppendStream::invalidate($path);
142	}
143	$written = ABJ_404_Solution_DiagnosticAppendStream::append($path, $line);
144	if ($written['status'] !== 'complete') {
145	if ($written['reason'] === 'open_failed') {
146	self::reportFailure('AJAX checkpoint file could not be opened: ' . $path);
147	return array('status' => 'failed', 'reason' => 'journal_open_failed');
148	}
149	self::reportFailure('AJAX checkpoint append/flush failed: ' . $path);
150	return array('status' => 'failed', 'reason' => 'append_flush_failed');
151	}
152	return array('status' => $status, 'reason' => $reason);
153	}
154
155	/**
156	* The emergency record written when the advisory lock never came free.
157	*
158	* Deliberately opens its own descriptor rather than reusing the
159	* request-scoped one: this path exists because the ordinary write path is
160	* stuck, so it must not depend on that path's state. It is also rare by
161	* construction (once per stuck lock), so the open it pays for is not the
162	* per-record cost DiagnosticAppendStream removes.
163	*
164	* @param array{path: string, record: array<string, mixed>, blocked_event: string, wait_us: int} $timeout
165	*/
166	private static function appendLockTimeoutRecord(array $timeout): void {
167	$path = $timeout['path'];
168	$blockedRecord = $timeout['record'];
169	$blockedEvent = $timeout['blocked_event'];
170	$waitUs = $timeout['wait_us'];
171	$timeoutRecord = $blockedRecord;
172	$timeoutRecord['event'] = 'lock_timeout';
173	$timeoutRecord['blocked_event'] = $blockedEvent;
174	$timeoutRecord['lock_wait_us'] = $waitUs;
175	$timeoutRecord['lock_timeout_us'] = self::LOCK_WAIT_TIMEOUT_US;
176	$json = json_encode($timeoutRecord, JSON_UNESCAPED_SLASHES);
177	if (!is_string($json)) {
178	self::reportFailure('AJAX checkpoint lock-timeout JSON encoding failed.');
179	return;
180	}
181	$handle = @fopen($path, 'ab');
182	if ($handle === false) {
183	self::reportFailure('AJAX checkpoint lock-timeout journal could not be opened: ' . $path);
184	return;
185	}
186	try {
187	$line = $json . "\n";
188	$written = @fwrite($handle, $line);
189	$flushed = @fflush($handle);
190	if ($written !== strlen($line) \|\| !$flushed) {
191	self::reportFailure('AJAX checkpoint lock-timeout record could not be appended: ' . $path);
192	}
193	} finally {
194	@fclose($handle);
195	}
196	}
197
198	/**
199	* @param array{status: string, reason: string, request_id: string, event: string, started_ns: int} $state
200	* @return array<string, mixed>
201	*/
202	private static function result(array $state): array {
203	$result = array(
204	'status' => $state['status'],
205	'request_id' => $state['request_id'],
206	'event' => $state['event'],
207	'elapsed_us' => self::elapsedMicroseconds($state['started_ns']),
208	);
209	if ($state['reason'] !== '') {
210	$result['reason'] = $state['reason'];
211	}
212	return $result;
213	}
214
215	/**
216	* A monotonic nanosecond counter, or 0 when the host has none.
217	*
218	* This measures the writer's OWN cost, so the reading has to be monotonic:
219	* a wall clock can step backwards under NTP and would report a write that
220	* took a full second as instantaneous. hrtime() has been core since PHP
221	* 7.3 and this plugin requires 7.4, so the only way it is missing is an
222	* explicit `disable_functions`. On such a host the honest answer is that
223	* the writer's cost is unmeasurable -- both readings return 0, so
224	* elapsedMicroseconds() reports 0 -- rather than a number fabricated from
225	* a different, non-monotonic time source. Keeping this class free of the
226	* clock service is deliberate: it is the last writer standing when the
227	* rest of the diagnostic stack is what is broken.
228	*/
229	private static function monotonicNanoseconds(): int {
230	return function_exists('hrtime') ? (int)hrtime(true) : 0;
231	}
232
233	private static function elapsedMicroseconds(int $startedNs): int {
234	return max(0, (int)round((self::monotonicNanoseconds() - $startedNs) / 1000));
235	}
236
237	private static function reportFailure(string $message): void {
238	abj404_logPhpFallback('ajax-checkpoint', $message);
239	}
240	}
241