404-solution / includes / diagnostics / AuthorizationLogTracer.php

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

241 lines 8.0 KB

Raw Download Zip

1	<?php
2
3	if (!defined('ABSPATH')) {
4	exit;
5	}
6
7	/**
8	* Durable attribution for the synchronous successful-authorization log call.
9	*
10	* Bruno's affected requests all wrote "AJAX authorized" and then went silent.
11	* The existing auth_check pair therefore proves that authorization began but
12	* cannot distinguish a logger call that made its line visible before its
13	* underlying file operation returned. This tracer reserves an outer pair
14	* before logger resolution and, while that call is active, lets the native
15	* Logging adapter attribute path resolution and the final write/return.
16	*
17	* State is a stack rather than a boolean: nested authorization calls cannot
18	* clear an outer call's context, and unrelated logging is a pure pass-through.
19	* Paths and messages never enter the checkpoint records.
20	*/
21	final class ABJ_404_Solution_AuthorizationLogTracer {
22
23	/** @var array<int, array{request_id: string, operation_id: string}> */
24	private static $contexts = array();
25
26	/** @var int */
27	private static $operationSequence = 0;
28
29	/**
30	* Trace logger resolution plus the successful authorization audit call.
31	*
32	* @template T
33	* @param callable(): T $work
34	* @return T
35	*/
36	public static function trace(callable $work) {
37	$requestId = self::requestId();
38	if ($requestId === '') {
39	return $work();
40	}
41
42	$operationId = self::operationId($requestId, 'authorize_admin_with_nonce');
43	$fields = array(
44	'operation_id' => $operationId,
45	'operation' => 'authorize_admin_with_nonce',
46	);
47	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent(
48	$requestId,
49	'auth_log_start',
50	$fields
51	);
52	self::$contexts[] = array(
53	'request_id' => $requestId,
54	'operation_id' => $operationId,
55	);
56	$startedAt = self::nowFloat();
57
58	try {
59	$result = $work();
60	} catch (Throwable $error) {
61	array_pop(self::$contexts);
62	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent(
63	$requestId,
64	'auth_log_end',
65	array_merge($fields, array(
66	'status' => 'error',
67	'elapsed_ms' => self::elapsedMilliseconds($startedAt),
68	'error' => self::errorSummary($error),
69	))
70	);
71	throw $error;
72	}
73
74	array_pop(self::$contexts);
75	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent(
76	$requestId,
77	'auth_log_end',
78	array_merge($fields, array(
79	'status' => 'complete',
80	'elapsed_ms' => self::elapsedMilliseconds($startedAt),
81	))
82	);
83	return $result;
84	}
85
86	/**
87	* Attribute one native logging sub-operation while trace() is active.
88	* Outside that scope this is behavior-identical to invoking $work directly.
89	*
90	* @template T
91	* @param callable(): T $work
92	* @return T
93	*/
94	public static function aroundOperation(string $operation, callable $work) {
95	$context = self::activeContext();
96	if ($context === null) {
97	if (class_exists('ABJ_404_Solution_PostAuthorizationFailureTracer')
98	&& ABJ_404_Solution_PostAuthorizationFailureTracer::isActive()) {
99	return ABJ_404_Solution_PostAuthorizationFailureTracer::aroundNativeOperation(
100	$operation,
101	$work
102	);
103	}
104	return $work();
105	}
106
107	$operationId = self::operationId($context['request_id'], $operation);
108	$fields = array(
109	'operation_id' => $operationId,
110	'parent_operation_id' => $context['operation_id'],
111	'operation' => $operation,
112	);
113	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent(
114	$context['request_id'],
115	'auth_log_operation_start',
116	$fields
117	);
118	$startedAt = self::nowFloat();
119	try {
120	$result = $work();
121	} catch (Throwable $error) {
122	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent(
123	$context['request_id'],
124	'auth_log_operation_end',
125	array_merge($fields, array(
126	'status' => 'error',
127	'elapsed_ms' => self::elapsedMilliseconds($startedAt),
128	'error' => self::errorSummary($error),
129	))
130	);
131	throw $error;
132	}
133
134	ABJ_404_Solution_AjaxCheckpointLogger::recordFrequent(
135	$context['request_id'],
136	'auth_log_operation_end',
137	array_merge($fields, array(
138	'status' => 'complete',
139	'elapsed_ms' => self::elapsedMilliseconds($startedAt),
140	'result' => self::resultSummary($result),
141	))
142	);
143	return $result;
144	}
145
146	/**
147	* @template T
148	* @param callable():T $work
149	* @return T
150	*/
151	public static function aroundRoutineOperation(
152	string $authorizationOperation,
153	string $routineOperation,
154	callable $work
155	) {
156	return self::aroundOperation(
157	$authorizationOperation,
158	static fn() => ABJ_404_Solution_RoutineLoggingBridge::trace(
159	$routineOperation,
160	array(),
161	$work
162	)
163	);
164	}
165
166	public static function isActive(): bool {
167	return self::activeContext() !== null;
168	}
169
170	/** @return array{request_id: string, operation_id: string}\|null */
171	private static function activeContext(): ?array {
172	$context = end(self::$contexts);
173	return is_array($context) ? $context : null;
174	}
175
176	private static function requestId(): string {
177	if (!class_exists('ABJ_404_Solution_AjaxDiagnosticRequestPolicy')) {
178	return '';
179	}
180	return ABJ_404_Solution_AjaxDiagnosticRequestPolicy::instrumentedRequestIdFromGlobalContext();
181	}
182
183	private static function operationId(string $requestId, string $operation): string {
184	self::$operationSequence++;
185	return substr(hash(
186	'sha256',
187	$requestId . '\|' . $operation . '\|' . self::$operationSequence
188	), 0, 12);
189	}
190
191	/** @return array<string, mixed> */
192	private static function errorSummary(Throwable $error): array {
193	$message = $error->getMessage();
194	return array(
195	'class' => self::safeClassName(get_class($error)),
196	'code' => is_int($error->getCode()) ? $error->getCode() : 0,
197	'message' => 'message#' . substr(hash('sha256', $message), 0, 12),
198	'message_length' => strlen($message),
199	);
200	}
201
202	/**
203	* @param mixed $result
204	* @return array{type: string, value?: bool\|int\|float\|string\|null}
205	*/
206	private static function resultSummary($result): array {
207	if (is_bool($result) \|\| is_int($result) \|\| is_float($result) \|\| $result === null) {
208	return array('type' => gettype($result), 'value' => $result);
209	}
210	return array('type' => is_object($result)
211	? 'object:' . self::safeClassName(get_class($result))
212	: gettype($result));
213	}
214
215	private static function safeClassName(string $class): string {
216	return preg_match('/^[A-Za-z_\\\\][A-Za-z0-9_\\\\]{0,159}$/', $class) === 1
217	? $class
218	: 'class#' . substr(hash('sha256', $class), 0, 12);
219	}
220
221	private static function nowFloat(): ?float {
222	if (function_exists('abj_clock')) {
223	return abj_clock()->nowFloat();
224	}
225	if (class_exists('ABJ_404_Solution_SystemClock')) {
226	return (new ABJ_404_Solution_SystemClock())->nowFloat();
227	}
228	return null;
229	}
230
231	private static function elapsedMilliseconds(?float $startedAt): ?int {
232	if ($startedAt === null) {
233	return null;
234	}
235	$finishedAt = self::nowFloat();
236	return $finishedAt === null
237	? null
238	: max(0, (int)round(($finishedAt - $startedAt) * 1000));
239	}
240	}
241