metasync / includes / class-metasync-error-logger.php

class-metasync-error-logger.php in Search Atlas SEO – OTTO AI SEO Automation for WordPress 2.7.2, at includes/class-metasync-error-logger.php

465 lines 16.9 KB

Raw Download Zip

1	<?php
2	/**
3	* Enhanced Error Logger with Categories and Hooks
4	*
5	* Implements structured error categorization with business logic categories
6	* for better integration with external monitoring tools.
7	*
8	* @package Metasync
9	* @subpackage Metasync/includes
10	* @since 1.0.0
11	* @author Engineering Team <[email protected]>
12	*/
13
14	// If this file is called directly, abort.
15	if (!defined('WPINC')) {
16	die;
17	}
18
19	/**
20	* Enhanced Error Logger Class
21	*
22	* Provides structured error logging with:
23	* - 8 business logic error categories
24	* - Standardized error codes (MS-XXXX format)
25	* - Structured log format with JSON context
26	* - WordPress action hooks for external monitoring
27	* - Error summary tracking in wp_options
28	*/
29	class Metasync_Error_Logger {
30
31	/**
32	* Error category constants
33	*/
34	const CATEGORY_API_RATE_LIMIT = 'API_RATE_LIMIT';
35	const CATEGORY_API_BACKOFF = 'API_BACKOFF';
36	const CATEGORY_EXECUTION_TIMEOUT = 'EXECUTION_TIMEOUT';
37	const CATEGORY_MEMORY_EXHAUSTED = 'MEMORY_EXHAUSTED';
38	const CATEGORY_QUEUE_OVERFLOW = 'QUEUE_OVERFLOW';
39	const CATEGORY_AUTHENTICATION_FAILURE = 'AUTHENTICATION_FAILURE';
40	const CATEGORY_DATABASE_ERROR = 'DATABASE_ERROR';
41	const CATEGORY_NETWORK_ERROR = 'NETWORK_ERROR';
42	const CATEGORY_OTTO_RENDER = 'OTTO_RENDER';
43	const CATEGORY_HEADLESS_DELIVERY = 'HEADLESS_DELIVERY';
44
45	/**
46	* Error codes mapping
47	* Format: MS-XXXX
48	*/
49	private static $error_codes = [
50	self::CATEGORY_API_RATE_LIMIT => 'MS-1001',
51	self::CATEGORY_API_BACKOFF => 'MS-1002',
52	self::CATEGORY_EXECUTION_TIMEOUT => 'MS-2001',
53	self::CATEGORY_MEMORY_EXHAUSTED => 'MS-2002',
54	self::CATEGORY_QUEUE_OVERFLOW => 'MS-3001',
55	self::CATEGORY_AUTHENTICATION_FAILURE => 'MS-4001',
56	self::CATEGORY_DATABASE_ERROR => 'MS-5001',
57	self::CATEGORY_NETWORK_ERROR => 'MS-6001',
58	self::CATEGORY_OTTO_RENDER => 'MS-7001',
59	self::CATEGORY_HEADLESS_DELIVERY => 'MS-8001',
60	];
61
62	/**
63	* Categories that only exist while an operator is troubleshooting.
64	*
65	* These record the plugin's OWN client-side throttling, not a site fault:
66	* the OTTO call budget was reached, or a retry was deferred. Both are the
67	* plugin working as designed, but they read as failures in the Error Logs
68	* panel and are a known source of false-alarm bug reports. They are only
69	* recorded while Debug Mode is on, and only shown while Debug Mode is on.
70	*/
71	const DEBUG_ONLY_CATEGORIES = [
72	self::CATEGORY_API_RATE_LIMIT,
73	self::CATEGORY_API_BACKOFF,
74	];
75
76	/**
77	* Non-alarming labels for categories whose raw name overstates severity.
78	*
79	* Presentation only — the stored category is never rewritten, so historical
80	* rows render softly too and no data migration is needed.
81	*/
82	private static $display_labels = [
83	self::CATEGORY_API_RATE_LIMIT => 'THROTTLED',
84	self::CATEGORY_API_BACKOFF => 'RETRY_SCHEDULED',
85	];
86
87	/**
88	* Severity level constants
89	*/
90	const SEVERITY_INFO = 'INFO';
91	const SEVERITY_WARNING = 'WARNING';
92	const SEVERITY_ERROR = 'ERROR';
93	const SEVERITY_CRITICAL = 'CRITICAL';
94
95	/**
96	* Option name for error summary storage
97	*/
98	const ERROR_SUMMARY_OPTION = 'metasync_error_summary';
99
100	/**
101	* Maximum number of unique errors to keep in summary
102	*/
103	const MAX_SUMMARY_ENTRIES = 100;
104
105	/**
106	* Log file name
107	*/
108	const LOG_FILE_NAME = 'metasync-errors.log';
109
110	/**
111	* Maximum log file size before rotation (10MB), mirroring the debug-mode
112	* log policy: current file plus a single .old rotation.
113	*/
114	const MAX_LOG_SIZE = 10485760; // 10MB in bytes
115
116	/**
117	* Main logging function
118	*
119	* Formats and writes structured error log with:
120	* - Timestamp
121	* - Category
122	* - Severity
123	* - Message
124	* - JSON context
125	*
126	* Also:
127	* - Fires WordPress action hook
128	* - Updates error summary in wp_options
129	*
130	* @param string $category One of the CATEGORY_* constants
131	* @param string $severity One of the SEVERITY_* constants
132	* @param string $message Human-readable error message
133	* @param array $context Additional context data (optional)
134	* @return bool True on success, false on failure
135	*/
136	public static function log($category, $severity, $message, $context = []) {
137	// Validate inputs
138	if (empty($category) \|\| empty($severity) \|\| empty($message)) {
139	return false;
140	}
141
142	// Throttling categories are diagnostics, not faults: skip them entirely
143	// unless an operator has Debug Mode on. Nothing is written, no summary
144	// entry is created, and the metasync_error_logged action does not fire.
145	if (self::is_suppressed_category($category)) {
146	return false;
147	}
148
149	// Get error code for this category
150	$error_code = self::$error_codes[$category] ?? 'MS-0000';
151
152	// Prepare full context with error code
153	$full_context = array_merge([
154	'error_code' => $error_code,
155	'severity' => $severity
156	], $context);
157
158	// Format timestamp — current_time() keeps the log line on the same
159	// WordPress-local clock as the error summary below, instead of the
160	// server/UTC clock date() uses.
161	$timestamp = current_time('Y-m-d H:i:s');
162
163	// Format log line: [YYYY-MM-DD HH:MM:SS] [CATEGORY] [SEVERITY] Message {context_json}
164	$log_line = sprintf(
165	"[%s] [%s] [%s] %s %s\n",
166	$timestamp,
167	$category,
168	$severity,
169	$message,
170	json_encode($full_context, JSON_UNESCAPED_SLASHES \| JSON_UNESCAPED_UNICODE)
171	);
172
173	// Write to dedicated log file
174	$log_written = self::write_to_log_file($log_line);
175
176	// Fire WordPress action hook for external monitoring
177	do_action('metasync_error_logged', $category, $error_code, $message, $full_context);
178
179	// Update error summary in database
180	self::update_error_summary($category, $error_code, $message, $full_context);
181
182	return $log_written;
183	}
184
185	/**
186	* Write log line to dedicated error log file
187	*
188	* @param string $log_line Formatted log line
189	* @return bool True on success, false on failure
190	*/
191	private static function write_to_log_file($log_line) {
192	// Directory creation, web-server protection, and writability
193	// guarantees live in Metasync_Data_Store so every writer agrees on
194	// the location; a false return means "no writable data directory".
195	$log_directory = Metasync_Data_Store::base_dir();
196	if (false === $log_directory) {
197	return false;
198	}
199
200	// Get log file path
201	$log_file = Metasync_Data_Store::file_path(self::LOG_FILE_NAME);
202	if (false === $log_file) {
203	return false;
204	}
205
206	// Serialize rotation and append across requests. Locking only the log
207	// file is insufficient because rename() changes the inode being locked.
208	$rotation_lock = @fopen($log_file . '.lock', 'c'); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_fopen -- streaming file I/O; WP_Filesystem cannot return a raw stream handle
209	if (false === $rotation_lock \|\| !flock($rotation_lock, LOCK_EX)) {
210	if (false !== $rotation_lock) {
211	fclose($rotation_lock); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_fclose -- operates on a native stream handle
212	}
213	error_log('Metasync_Error_Logger: Failed to lock log file: ' . $log_file); // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_error_log -- plugin logger sink / last-resort fallback
214	return false;
215	}
216
217	// Rotate while holding the stable sidecar lock so concurrent requests
218	// cannot both unlink/rename the same file or append to the old inode.
219	$log_size = file_exists($log_file) ? filesize($log_file) : false;
220	if (false !== $log_size && $log_size >= self::MAX_LOG_SIZE) {
221	$backup = $log_file . '.old';
222	if (file_exists($backup)) {
223	@wp_delete_file($backup);
224	}
225	@rename($log_file, $backup); // phpcs:ignore WordPress.WP.AlternativeFunctions.rename_rename -- atomic same-filesystem replace; WP_Filesystem::move() needs credential bootstrapping on non-direct hosts
226	}
227
228	// Append to log file with file locking
229	$result = @file_put_contents($log_file, $log_line, FILE_APPEND \| LOCK_EX);
230	flock($rotation_lock, LOCK_UN);
231	fclose($rotation_lock); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_fclose -- operates on a native stream handle
232
233	if ($result === false) {
234	error_log('Metasync_Error_Logger: Failed to write to log file: ' . $log_file); // phpcs:ignore WordPress.PHP.DevelopmentFunctions.error_log_error_log -- plugin logger sink / last-resort fallback
235	return false;
236	}
237
238	// Set file permissions if file was just created
239	if (!file_exists($log_file) \|\| filesize($log_file) === strlen($log_line)) {
240	@chmod($log_file, 0644); // phpcs:ignore WordPress.WP.AlternativeFunctions.file_system_operations_chmod -- direct POSIX permission change; WP_Filesystem would prompt for FTP credentials on non-direct hosts
241	}
242
243	return true;
244	}
245
246	/**
247	* Update error summary in wp_options
248	*
249	* Tracks last 100 unique errors with counts.
250	* Unique key is based on category + first 50 chars of message.
251	*
252	* @param string $category Error category
253	* @param string $code Error code
254	* @param string $message Error message
255	* @param array $context Error context
256	*/
257	private static function update_error_summary($category, $code, $message, $context) {
258	// Get existing summary
259	$summary = get_option(self::ERROR_SUMMARY_OPTION, []);
260
261	if (!is_array($summary)) {
262	$summary = [];
263	}
264
265	// Create unique key from category + first 50 chars of message
266	$message_preview = substr($message, 0, 50);
267	$key = $category . '\|' . $message_preview;
268
269	// Initialize entry if it doesn't exist
270	if (!isset($summary[$key])) {
271	$summary[$key] = [
272	'category' => $category,
273	'code' => $code,
274	'message' => $message,
275	'count' => 0,
276	'first_seen' => current_time('mysql'),
277	'last_seen' => current_time('mysql'),
278	'severity' => isset($context['severity']) ? $context['severity'] : 'UNKNOWN'
279	];
280	}
281
282	// Update count and last seen time
283	$summary[$key]['count']++;
284	$summary[$key]['last_seen'] = current_time('mysql');
285
286	// Keep only last 100 unique errors (prune oldest)
287	if (count($summary) > self::MAX_SUMMARY_ENTRIES) {
288	// Sort by last_seen (newest first)
289	uasort($summary, function($a, $b) {
290	return strtotime($b['last_seen']) - strtotime($a['last_seen']);
291	});
292
293	// Keep only the most recent entries
294	$summary = array_slice($summary, 0, self::MAX_SUMMARY_ENTRIES, true);
295	}
296
297	// Save to database
298	update_option(self::ERROR_SUMMARY_OPTION, $summary);
299	}
300
301	/**
302	* Get error summary from wp_options
303	*
304	* @return array Error summary array
305	*/
306	public static function get_error_summary() {
307	$summary = get_option(self::ERROR_SUMMARY_OPTION, []);
308	return is_array($summary) ? $summary : [];
309	}
310
311	/**
312	* Clear error summary
313	*
314	* @return bool True on success
315	*/
316	public static function clear_error_summary() {
317	return delete_option(self::ERROR_SUMMARY_OPTION);
318	}
319
320	/**
321	* Whether a category is withheld on this request.
322	*
323	* True for the throttling categories while Debug Mode is off. Used both to
324	* skip recording and to filter what the Error Logs panel shows, so rows
325	* recorded before this behaviour existed are hidden too.
326	*
327	* @param string $category Category name
328	* @return bool True when the category should be withheld
329	*/
330	public static function is_suppressed_category($category) {
331	if (!in_array($category, self::DEBUG_ONLY_CATEGORIES, true)) {
332	return false;
333	}
334
335	return !(class_exists('Metasync_Debug_Mode_Manager')
336	&& Metasync_Debug_Mode_Manager::is_enabled());
337	}
338
339	/**
340	* Non-alarming label to display for a category.
341	*
342	* @param string $category Stored category name
343	* @return string Label for display
344	*/
345	public static function get_display_label($category) {
346	return self::$display_labels[$category] ?? $category;
347	}
348
349	/**
350	* Get error summary for display, with withheld categories removed.
351	*
352	* @return array Error summary entries safe to show on this request
353	*/
354	public static function get_visible_error_summary() {
355	// get_error_summary() already guarantees an array.
356	$summary = self::get_error_summary();
357
358	foreach ($summary as $key => $entry) {
359	$category = is_array($entry) ? ($entry['category'] ?? '') : '';
360	if ($category !== '' && self::is_suppressed_category($category)) {
361	unset($summary[$key]);
362	}
363	}
364
365	return $summary;
366	}
367
368	/**
369	* Get error code for a category
370	*
371	* @param string $category Error category
372	* @return string Error code or 'MS-0000' if not found
373	*/
374	public static function get_error_code($category) {
375	return self::$error_codes[$category] ?? 'MS-0000';
376	}
377
378	/**
379	* Get all error codes mapping
380	*
381	* @return array Error codes array
382	*/
383	public static function get_all_error_codes() {
384	return self::$error_codes;
385	}
386	}
387
388
389	/**
390	* Check Action Scheduler queue for overflow
391	* This checks if pending actions exceed 1000 and logs QUEUE_OVERFLOW error
392	*
393	* @param bool $force_check If true, bypasses transient throttling (for manual testing)
394	* @return int\|false Returns pending count if checked, false if skipped
395	*/
396	function metasync_check_action_scheduler_queue_overflow($force_check = false) {
397	// Only check if Action Scheduler is available
398	if (!class_exists('ActionScheduler_Store')) {
399	return false;
400	}
401
402	// Only check if Error Logger is available
403	if (!class_exists('Metasync_Error_Logger')) {
404	return false;
405	}
406
407	// Throttle: Only check once per hour to avoid excessive logging (unless forced)
408	if (!$force_check) {
409	$transient_key = 'metasync_queue_overflow_check';
410	$last_check = get_transient($transient_key);
411
412	if ($last_check !== false) {
413	return false; // Already checked recently
414	}
415	}
416
417	try {
418	$store = ActionScheduler_Store::instance();
419
420	// Get count of pending actions
421	$pending_count = (int) $store->query_actions([
422	'status' => ActionScheduler_Store::STATUS_PENDING,
423	'per_page' => 0, // We only need count
424	], 'count');
425
426	// Check if queue overflow threshold is exceeded (>1000)
427	if ($pending_count > 1000) {
428	Metasync_Error_Logger::log(
429	Metasync_Error_Logger::CATEGORY_QUEUE_OVERFLOW,
430	Metasync_Error_Logger::SEVERITY_WARNING,
431	'Action Scheduler queue overflow - too many pending actions',
432	[
433	'pending_count' => $pending_count,
434	'threshold' => 1000,
435	'queue_system' => 'Action Scheduler',
436	'operation' => 'queue_processing'
437	]
438	);
439	}
440
441	// Set transient to throttle future checks (1 hour) - only if not forced
442	if (!$force_check) {
443	$transient_key = 'metasync_queue_overflow_check';
444	set_transient($transient_key, time(), HOUR_IN_SECONDS);
445	}
446
447	return $pending_count;
448	} catch (Exception $e) {
449	// Fail silently to prevent breaking queue processing
450	// error_log('MetaSync: Failed to check queue overflow: ' . $e->getMessage());
451	return false;
452	}
453	}
454
455	// Hook into Action Scheduler before processing queue
456	add_action('action_scheduler_before_process_queue', 'metasync_check_action_scheduler_queue_overflow', 10, 0);
457
458	// Also check on shutdown (for immediate detection, throttled)
459	add_action('shutdown', function() {
460	// Only check in admin or if triggered manually
461	if (is_admin() \|\| isset($_GET['metasync_check_queue'])) { // phpcs:ignore WordPress.Security.NonceVerification.Recommended -- read-only, throttled queue check
462	metasync_check_action_scheduler_queue_overflow();
463	}
464	}, 999);
465