[3.0] Improve ErrorHandlerService error logging performance and diagnostics

Sources/Services/ErrorHandlerService.php

@@ -57,6 +57,11 @@ class ErrorHandlerService
 		\SQLite3Exception::class => 'cache',
 	];
 
+	/**
+	 * Maximum number of errors to collect before flushing the batch.
+	 */
+	public int $batch_size = 10;
+
 	/****************
 	 * Public methods
 	 ****************/
@@ -179,10 +184,12 @@ public function call(int $error_level, string $error_string, string $file, int $
 	 */
 	public function catch(\Throwable $e): void
 	{
-		$message = Lang::txtExists($e->getMessage(), file: 'Errors') ? Lang::getTxt($e->getMessage(), file: 'Errors') : $e->getMessage();
+		$message = Lang::txtExists($e->getMessage(), file: 'Errors')
+			? Lang::getTxt($e->getMessage(), file: 'Errors')
+			: $e->getMessage();
 
 		if (!empty(Config::$modSettings['enableErrorLogging'])) {
-			$this->log($message, 'general', $e->getFile(), $e->getLine(), $e->getTrace());
+			$this->log($e::class . ': ' . $message, 'general', $e->getFile(), $e->getLine(), $e->getTrace());
 		}
 
 		$this->fatal($message, false);
@@ -208,30 +215,27 @@ public function log(string $error_message, string|bool $error_type = 'general',
 		static $tried_hook = false;
 		static $error_call = 0;
 		static $error_batch = [];
-		static $batch_size = 10;
 		static $shutdown_registered = false;
 
-		$error_call++;
-
-		// Collect a backtrace
-		if (!DebugUtils::isDebugEnabled()) {
-			$backtrace = $backtrace ?? debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
-		} else {
-			// This is how to keep the args but skip the objects.
-			$backtrace = $backtrace ?? debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS & DEBUG_BACKTRACE_PROVIDE_OBJECT);
+		// Check if error logging is actually on.
+		if (empty(Config::$modSettings['enableErrorLogging'])) {
+			return $error_message;
 		}
 
-		// Are we in a loop?
+		$error_call++;
+
+		// Are we in a loop? The count is how deep this call is: logging an
+		// error is allowed to produce one more, but a third means that
+		// whatever this depends on fails every time it is asked, and
+		// going round again would not end.
 		if ($error_call > 2) {
 			var_dump($backtrace);
 
 			die('Error: loop detected. The database may have failed or crashed.');
 		}
 
-		// Check if error logging is actually on.
-		if (empty(Config::$modSettings['enableErrorLogging'])) {
-			return $error_message;
-		}
+		// Collect a backtrace
+		$backtrace = $backtrace ?? debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);
 
 		// Basically, htmlspecialchars it minus &. (for entities!)
 		$error_message = strtr($error_message, ['<' => '&lt;', '>' => '&gt;', '"' => '&quot;']);
@@ -281,8 +285,12 @@ public function log(string $error_message, string|bool $error_type = 'general',
 		// Make sure the category that was specified is a valid one
 		$error_type = \in_array($error_type, $this->known_error_types) && $error_type !== true ? $error_type : 'general';
 
-		// Leave out the call to this method.
-		array_splice($backtrace, 0, 1);
+		// Remove any ErrorHandler frames from the backtrace.
+		$backtrace = array_values(array_filter(
+			$backtrace,
+			// Intentionally not matching exact class names here.
+			static fn(array $trace): bool => !isset($trace['class']) || !str_contains($trace['class'], 'ErrorHandler'),
+		));
 
 		// Never log call arguments or bound objects.
 		//
@@ -331,15 +339,15 @@ public function log(string $error_message, string|bool $error_type = 'general',
 			}
 
 			// Flush batch when threshold reached.
-			if (\count($error_batch) >= $batch_size) {
+			if (\count($error_batch) >= $this->batch_size) {
 				$this->flushErrorBatch($error_batch);
 				$error_batch = [];
 			}
 
 			// Register shutdown function to flush remaining batch.
 			if (!$shutdown_registered) {
 				register_shutdown_function(function () use (&$error_batch) {
-					if (!empty($error_batch)) {
+					if ($error_batch !== []) {
 						$this->flushErrorBatch($error_batch);
 					}
 				});
@@ -416,7 +424,7 @@ public function fatalLang(string $error, string|bool $log = 'general', array $sp
 		}
 
 		// Attempt to load the text string.
-		$error_message = Lang::getTxt($error, $sprintf, file: 'Errors');
+		$error_message = Lang::getTxt($error, $sprintf, file: $file);
 
 		// Send a custom header if we have a custom message.
 		if (isset($_REQUEST['js']) || isset($_REQUEST['xml']) || isset($_REQUEST['ajax'])) {
@@ -783,17 +791,57 @@ protected function sendHttpStatus(int $code, string $message = ''): void
 	 * Flush batched errors to database in a single multi-row operation.
 	 * This is much faster than individual inserts, especially during high-error scenarios.
 	 *
-	 * @param array $errors Array of error info arrays to flush
+	 * @param array $errors Array of error info arrays to flush.
 	 */
 	private function flushErrorBatch(array $errors): void
 	{
-		if (empty($errors)) {
-			return;
-		}
+		$columns = [
+			'id_member' => 'int',
+			'log_time' => 'int',
+			'ip' => 'inet',
+			'url' => 'string',
+			'message' => 'string',
+			'session' => 'string',
+			'error_type' => 'string',
+			'file' => 'string',
+			'line' => 'int',
+			'backtrace' => 'string',
+		];
 
-		// Insert all batched errors in one query
-		foreach ($errors as $error_info) {
-			Db::$db->error_insert($error_info);
-		}
+		$data = [];
+
+		foreach ($errors as $error_array) {
+			if (!isset($error_array['ip'])) {
+				$error_array = array_combine(
+					array_keys($columns),
+					$error_array,
+				);
+			}
+
+			if (filter_var($error_array['ip'], FILTER_VALIDATE_IP) === false) {
+				$error_array['ip'] = null;
+			}
+
+			$data[] = [
+				$error_array['id_member'],
+				$error_array['log_time'],
+				$error_array['ip'],
+				$error_array['url'],
+				$error_array['message'],
+				$error_array['session'],
+				$error_array['error_type'],
+				$error_array['file'],
+				$error_array['line'],
+				$error_array['backtrace'],
+			];
+		}
+
+		Db::$db->insert(
+			'insert',
+			'{db_prefix}log_errors',
+			$columns,
+			$data,
+			[],
+		);
 	}
 }

tests/Integration/ErrorHandlerServiceTest.php

@@ -0,0 +1,140 @@
+<?php
+
+declare(strict_types=1);
+
+namespace SMF\Tests\Integration;
+
+use PHPUnit\Framework\Attributes\CoversClass;
+use SMF\Infrastructure\Container;
+use SMF\Config;
+use SMF\Db\DatabaseApi as Db;
+use SMF\ErrorHandler;
+use SMF\Services\ErrorHandlerService;
+
+/**
+ * Tests error logging against an installed forum.
+ */
+#[CoversClass(ErrorHandler::class)]
+#[CoversClass(ErrorHandlerService::class)]
+class ErrorHandlerServiceTest extends IntegrationTestCase
+{
+	/**
+	 * Verifies that a full error batch is written to the error log.
+	 */
+	public function testFullBatchIsWrittenToErrorLog(): void
+	{
+		$marker = 'ErrorHandlerServiceTest-' . bin2hex(random_bytes(8));
+		$service = new ErrorHandlerService();
+		$service->batch_size = 2;
+
+		$this->assertNoErrorsLogged();
+		$last_error_id = $this->lastErrorId();
+
+		$service->log($marker . '-0',  'Test');
+
+		$num_errors =  $this->queryRow(
+			'SELECT message
+			FROM {db_prefix}log_errors
+			WHERE message LIKE {string:pattern}
+				AND id_error > {int:last_error_id}',
+			[
+				'pattern' => $marker . '-%',
+				'last_error_id' => $last_error_id,
+			],
+		);
+
+		$this->assertNull($num_errors);
+
+		ErrorHandler::log($marker . '-1',  'Test');
+
+		$num_errors = $this->queryRow(
+			'SELECT COUNT(*)
+			FROM {db_prefix}log_errors
+			WHERE message LIKE {string:pattern}
+				AND id_error > {int:last_error_id}',
+			[
+				'pattern' => $marker . '-%',
+				'last_error_id' => $last_error_id,
+			],
+		);
+
+		$this->assertEquals('2', current($num_errors));
+	}
+
+	/**
+	 * Verifies that undefined errors use the undefined_vars error type.
+	 */
+	public function tesstUndefinedErrors(): void
+	{
+		$marker = 'Undefined variable: $my_special_error_' . bin2hex(random_bytes(8));
+		Config::$modSettings['enableErrorLogging'] = '1';
+
+		$this->assertNoErrorsLogged();
+		$last_error_id = $this->lastErrorId();
+
+		$error_reporting = error_reporting();
+		error_reporting(E_USER_WARNING);
+		set_error_handler(ErrorHandler::call(...));
+		trigger_error($marker, E_USER_WARNING);
+		restore_error_handler();
+		error_reporting($error_reporting);
+
+		$row = $this->queryRow(
+			'SELECT error_type
+			FROM {db_prefix}log_errors
+			WHERE message = {string:message}
+			ORDER BY id_error DESC
+			LIMIT 1',
+			[
+				'message' => '%: ' . $marker,
+			],
+		);
+
+		$this->assertNotNull($row);
+		$this->assertSame('undefined_vars', $row['error_type']);
+	}
+
+/**
+ * Verifies that undefined errors use the undefined_vars error type and log a backtrace.
+ */
+public function testUndefinedErrors(): void
+{
+	$marker = 'Undefined variable: $my_special_error_' . bin2hex(random_bytes(8));
+	Config::$modSettings['enableErrorLogging'] = '1';
+
+	$this->assertNoErrorsLogged();
+	$last_error_id = $this->lastErrorId();
+
+	$error_reporting = error_reporting();
+	error_reporting(E_USER_WARNING);
+	set_error_handler(ErrorHandler::call(...));
+	trigger_error($marker, E_USER_WARNING);
+	restore_error_handler();
+	error_reporting($error_reporting);
+
+	$row = $this->queryRow(
+		'SELECT error_type, backtrace
+		FROM {db_prefix}log_errors
+		WHERE message = {string:message}
+		ORDER BY id_error DESC
+		LIMIT 1',
+		[
+			'message' => E_USER_WARNING . ': ' . $marker,
+		],
+	);
+
+	$this->assertNotNull($row);
+	$this->assertSame('undefined_vars', $row['error_type']);
+
+	$backtrace = json_decode($row['backtrace'], true);
+
+	$this->assertIsArray($backtrace);
+	$this->assertIsList($backtrace);
+	$this->assertNotEmpty($backtrace);
+
+	$this->assertArrayHasKey('file', $backtrace[0]);
+	$this->assertArrayHasKey('function', $backtrace[0]);
+	$this->assertSame(__FILE__, $backtrace[0]['file']);
+	$this->assertSame('trigger_error', $backtrace[0]['function']);
+}
+}

tests/Integration/Installation.php

@@ -82,6 +82,9 @@ private static function connect(): string
 		// index.php builds this before anything can ask for a service.
 		Container::init();
 
+		// Flush any errors immediately.
+		Container::getInstance()->get(\SMF\Services\ErrorHandlerService::class)->batch_size = 1;
+
 		try {
 			// non_fatal, or a refused connection ends the process with SMF's own
 			// database error page instead of letting us report it here.

tests/Integration/IntegrationTestCase.php

@@ -270,7 +270,7 @@ protected function rawSetting(string $variable): ?string
 	 *
 	 * @return int The id, or 0 when nothing has ever been logged.
 	 */
-	private function lastErrorId(): int
+	protected function lastErrorId(): int
 	{
 		$request = Db::$db->query(
 			'SELECT COALESCE(MAX(id_error), 0) AS id_error