diff --git a/Sources/Services/ErrorHandlerService.php b/Sources/Services/ErrorHandlerService.php index 793c7cb37a..fb529e2f5c 100644 --- a/Sources/Services/ErrorHandlerService.php +++ b/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, ['<' => '<', '>' => '>', '"' => '"']); @@ -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,7 +339,7 @@ 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 = []; } @@ -339,7 +347,7 @@ public function log(string $error_message, string|bool $error_type = 'general', // 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, + [], + ); } } diff --git a/tests/Integration/ErrorHandlerServiceTest.php b/tests/Integration/ErrorHandlerServiceTest.php new file mode 100644 index 0000000000..2fa5714f34 --- /dev/null +++ b/tests/Integration/ErrorHandlerServiceTest.php @@ -0,0 +1,140 @@ +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']); +} +} diff --git a/tests/Integration/Installation.php b/tests/Integration/Installation.php index 4505b2675f..8fcdb851dd 100644 --- a/tests/Integration/Installation.php +++ b/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. diff --git a/tests/Integration/IntegrationTestCase.php b/tests/Integration/IntegrationTestCase.php index b540e9158e..c5c631b18f 100644 --- a/tests/Integration/IntegrationTestCase.php +++ b/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