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

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

484 lines 16.6 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	// Get log directory (same as Log_Manager uses)
193	$log_directory = WP_CONTENT_DIR . '/metasync_data';
194
195	// Create directory if it doesn't exist
196	if (!is_dir($log_directory)) {
197	if (!@mkdir($log_directory, 0755, true)) {
198	error_log('Metasync_Error_Logger: Failed to create log directory: ' . $log_directory);
199	return false;
200	}
201	}
202
203	// Protect log directory from direct web access
204	$htaccess_file = $log_directory . '/.htaccess';
205	if (!file_exists($htaccess_file)) {
206	@file_put_contents($htaccess_file, "Order deny,allow\nDeny from all\n");
207	}
208	$index_file = $log_directory . '/index.php';
209	if (!file_exists($index_file)) {
210	@file_put_contents($index_file, "<?php\n// Silence is golden\n");
211	}
212
213	// Verify directory is writable
214	if (!is_writable($log_directory)) {
215	@chmod($log_directory, 0755);
216	if (!is_writable($log_directory)) {
217	error_log('Metasync_Error_Logger: Directory not writable: ' . $log_directory);
218	return false;
219	}
220	}
221
222	// Get log file path
223	$log_file = wp_normalize_path($log_directory . '/' . self::LOG_FILE_NAME);
224
225	// Serialize rotation and append across requests. Locking only the log
226	// file is insufficient because rename() changes the inode being locked.
227	$rotation_lock = @fopen($log_file . '.lock', 'c');
228	if (false === $rotation_lock \|\| !flock($rotation_lock, LOCK_EX)) {
229	if (false !== $rotation_lock) {
230	fclose($rotation_lock);
231	}
232	error_log('Metasync_Error_Logger: Failed to lock log file: ' . $log_file);
233	return false;
234	}
235
236	// Rotate while holding the stable sidecar lock so concurrent requests
237	// cannot both unlink/rename the same file or append to the old inode.
238	$log_size = file_exists($log_file) ? filesize($log_file) : false;
239	if (false !== $log_size && $log_size >= self::MAX_LOG_SIZE) {
240	$backup = $log_file . '.old';
241	if (file_exists($backup)) {
242	@unlink($backup);
243	}
244	@rename($log_file, $backup);
245	}
246
247	// Append to log file with file locking
248	$result = @file_put_contents($log_file, $log_line, FILE_APPEND \| LOCK_EX);
249	flock($rotation_lock, LOCK_UN);
250	fclose($rotation_lock);
251
252	if ($result === false) {
253	error_log('Metasync_Error_Logger: Failed to write to log file: ' . $log_file);
254	return false;
255	}
256
257	// Set file permissions if file was just created
258	if (!file_exists($log_file) \|\| filesize($log_file) === strlen($log_line)) {
259	@chmod($log_file, 0644);
260	}
261
262	return true;
263	}
264
265	/**
266	* Update error summary in wp_options
267	*
268	* Tracks last 100 unique errors with counts.
269	* Unique key is based on category + first 50 chars of message.
270	*
271	* @param string $category Error category
272	* @param string $code Error code
273	* @param string $message Error message
274	* @param array $context Error context
275	*/
276	private static function update_error_summary($category, $code, $message, $context) {
277	// Get existing summary
278	$summary = get_option(self::ERROR_SUMMARY_OPTION, []);
279
280	if (!is_array($summary)) {
281	$summary = [];
282	}
283
284	// Create unique key from category + first 50 chars of message
285	$message_preview = substr($message, 0, 50);
286	$key = $category . '\|' . $message_preview;
287
288	// Initialize entry if it doesn't exist
289	if (!isset($summary[$key])) {
290	$summary[$key] = [
291	'category' => $category,
292	'code' => $code,
293	'message' => $message,
294	'count' => 0,
295	'first_seen' => current_time('mysql'),
296	'last_seen' => current_time('mysql'),
297	'severity' => isset($context['severity']) ? $context['severity'] : 'UNKNOWN'
298	];
299	}
300
301	// Update count and last seen time
302	$summary[$key]['count']++;
303	$summary[$key]['last_seen'] = current_time('mysql');
304
305	// Keep only last 100 unique errors (prune oldest)
306	if (count($summary) > self::MAX_SUMMARY_ENTRIES) {
307	// Sort by last_seen (newest first)
308	uasort($summary, function($a, $b) {
309	return strtotime($b['last_seen']) - strtotime($a['last_seen']);
310	});
311
312	// Keep only the most recent entries
313	$summary = array_slice($summary, 0, self::MAX_SUMMARY_ENTRIES, true);
314	}
315
316	// Save to database
317	update_option(self::ERROR_SUMMARY_OPTION, $summary);
318	}
319
320	/**
321	* Get error summary from wp_options
322	*
323	* @return array Error summary array
324	*/
325	public static function get_error_summary() {
326	$summary = get_option(self::ERROR_SUMMARY_OPTION, []);
327	return is_array($summary) ? $summary : [];
328	}
329
330	/**
331	* Clear error summary
332	*
333	* @return bool True on success
334	*/
335	public static function clear_error_summary() {
336	return delete_option(self::ERROR_SUMMARY_OPTION);
337	}
338
339	/**
340	* Whether a category is withheld on this request.
341	*
342	* True for the throttling categories while Debug Mode is off. Used both to
343	* skip recording and to filter what the Error Logs panel shows, so rows
344	* recorded before this behaviour existed are hidden too.
345	*
346	* @param string $category Category name
347	* @return bool True when the category should be withheld
348	*/
349	public static function is_suppressed_category($category) {
350	if (!in_array($category, self::DEBUG_ONLY_CATEGORIES, true)) {
351	return false;
352	}
353
354	return !(class_exists('Metasync_Debug_Mode_Manager')
355	&& Metasync_Debug_Mode_Manager::is_enabled());
356	}
357
358	/**
359	* Non-alarming label to display for a category.
360	*
361	* @param string $category Stored category name
362	* @return string Label for display
363	*/
364	public static function get_display_label($category) {
365	return self::$display_labels[$category] ?? $category;
366	}
367
368	/**
369	* Get error summary for display, with withheld categories removed.
370	*
371	* @return array Error summary entries safe to show on this request
372	*/
373	public static function get_visible_error_summary() {
374	// get_error_summary() already guarantees an array.
375	$summary = self::get_error_summary();
376
377	foreach ($summary as $key => $entry) {
378	$category = is_array($entry) ? ($entry['category'] ?? '') : '';
379	if ($category !== '' && self::is_suppressed_category($category)) {
380	unset($summary[$key]);
381	}
382	}
383
384	return $summary;
385	}
386
387	/**
388	* Get error code for a category
389	*
390	* @param string $category Error category
391	* @return string Error code or 'MS-0000' if not found
392	*/
393	public static function get_error_code($category) {
394	return self::$error_codes[$category] ?? 'MS-0000';
395	}
396
397	/**
398	* Get all error codes mapping
399	*
400	* @return array Error codes array
401	*/
402	public static function get_all_error_codes() {
403	return self::$error_codes;
404	}
405	}
406
407
408	/**
409	* Check Action Scheduler queue for overflow
410	* This checks if pending actions exceed 1000 and logs QUEUE_OVERFLOW error
411	*
412	* @param bool $force_check If true, bypasses transient throttling (for manual testing)
413	* @return int\|false Returns pending count if checked, false if skipped
414	*/
415	function metasync_check_action_scheduler_queue_overflow($force_check = false) {
416	// Only check if Action Scheduler is available
417	if (!class_exists('ActionScheduler_Store')) {
418	return false;
419	}
420
421	// Only check if Error Logger is available
422	if (!class_exists('Metasync_Error_Logger')) {
423	return false;
424	}
425
426	// Throttle: Only check once per hour to avoid excessive logging (unless forced)
427	if (!$force_check) {
428	$transient_key = 'metasync_queue_overflow_check';
429	$last_check = get_transient($transient_key);
430
431	if ($last_check !== false) {
432	return false; // Already checked recently
433	}
434	}
435
436	try {
437	$store = ActionScheduler_Store::instance();
438
439	// Get count of pending actions
440	$pending_count = (int) $store->query_actions([
441	'status' => ActionScheduler_Store::STATUS_PENDING,
442	'per_page' => 0, // We only need count
443	], 'count');
444
445	// Check if queue overflow threshold is exceeded (>1000)
446	if ($pending_count > 1000) {
447	Metasync_Error_Logger::log(
448	Metasync_Error_Logger::CATEGORY_QUEUE_OVERFLOW,
449	Metasync_Error_Logger::SEVERITY_WARNING,
450	'Action Scheduler queue overflow - too many pending actions',
451	[
452	'pending_count' => $pending_count,
453	'threshold' => 1000,
454	'queue_system' => 'Action Scheduler',
455	'operation' => 'queue_processing'
456	]
457	);
458	}
459
460	// Set transient to throttle future checks (1 hour) - only if not forced
461	if (!$force_check) {
462	$transient_key = 'metasync_queue_overflow_check';
463	set_transient($transient_key, time(), HOUR_IN_SECONDS);
464	}
465
466	return $pending_count;
467	} catch (Exception $e) {
468	// Fail silently to prevent breaking queue processing
469	// error_log('MetaSync: Failed to check queue overflow: ' . $e->getMessage());
470	return false;
471	}
472	}
473
474	// Hook into Action Scheduler before processing queue
475	add_action('action_scheduler_before_process_queue', 'metasync_check_action_scheduler_queue_overflow', 10, 0);
476
477	// Also check on shutdown (for immediate detection, throttled)
478	add_action('shutdown', function() {
479	// Only check in admin or if triggered manually
480	if (is_admin() \|\| isset($_GET['metasync_check_queue'])) {
481	metasync_check_action_scheduler_queue_overflow();
482	}
483	}, 999);
484