From 07223c678990b0ae1449b2021d4518fe498edfb8 Mon Sep 17 00:00:00 2001 From: albertlast Date: Tue, 1 Sep 2026 10:06:58 +0200 Subject: [PATCH] Counts errors that are on the stack, not errors that happened The guard that stops error logging looping is a count of how deep the call is, and it was only cleared by reaching the end of the method. Returning early because logging is switched off skipped that, so the count kept climbing and the third error in a request died with a backtrace and 'loop detected' even though nothing had recursed. Balancing the count in a finally covers that return, and any error raised between the two, without depending on where the method ends up leaving. Signed-off-by: albertlast --- Sources/Services/ErrorHandlerService.php | 245 ++++++++++++----------- tests/Unit/ErrorHandlerServiceTest.php | 90 +++++++++ 2 files changed, 216 insertions(+), 119 deletions(-) create mode 100644 tests/Unit/ErrorHandlerServiceTest.php diff --git a/Sources/Services/ErrorHandlerService.php b/Sources/Services/ErrorHandlerService.php index 4a475f5ac6..1fdcfcfdef 100644 --- a/Sources/Services/ErrorHandlerService.php +++ b/Sources/Services/ErrorHandlerService.php @@ -213,145 +213,152 @@ public function log(string $error_message, string|bool $error_type = 'general', $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); - } - - // Are we in a loop? - 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; - } - - // Basically, htmlspecialchars it minus &. (for entities!) - $error_message = strtr($error_message, ['<' => '<', '>' => '>', '"' => '"']); - - $error_message = strtr($error_message, ['<br />' => '
', '<br>' => '
', '<b>' => '', '</b>' => '', "\n" => '
']); - - // Add a file and line to the error message? - // Don't use the actual txt entries for file and line. - // Instead use %1$s for file and %2$s for line. - // Windows style slashes don't play well, lets convert them to the UNIX style. - $file = str_replace('\\', '/', $file); - - // Find the best path and query string we can... - if (SMF === 'SSI') { - $request_url = ($_SERVER['REQUEST_SCHEME'] ?? 'http') . '://' . ($_SERVER['SERVER_NAME'] ?? 'unknown') . '/' . ltrim($_SERVER['REQUEST_URI'] ?? (($_SERVER['DOCUMENT_URI'] ?? $_SERVER['SCRIPT_NAME'] ?? 'unknown.php') . (!empty($_SERVER['QUERY_STRING']) ? '?' . $_SERVER['QUERY_STRING'] : '')), '/'); - } elseif (str_starts_with(($_SERVER['REQUEST_URL'] ?? ''), Config::$boardurl)) { - $request_url = substr($_SERVER['REQUEST_URL'], \strlen(Config::$boardurl)); - } else { - $request_url = ($_SERVER['REQUEST_URL'] ?? ''); - } + try { + // 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); + } - // Don't log the session hash in the url twice, it's a waste. - $request_url = Utils::htmlspecialchars(preg_replace(['~([?&;]sesc)=[^&;]+~', '~' . session_name() . '=' . session_id() . '[&;]~'], ['$1', ''], $request_url)); + // 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); - // Just so we know what board error messages are from. - if (isset($_POST['board']) && !isset($_GET['board']) && SMF !== 'SSI') { - $request_url .= ($request_url == '' ? 'board=' : ';board=') . $_POST['board']; - } + die('Error: loop detected. The database may have failed or crashed.'); + } - // This prevents us from infinite looping if the hook or call produces an error. - $other_error_types = []; + // Check if error logging is actually on. + if (empty(Config::$modSettings['enableErrorLogging'])) { + return $error_message; + } - // Exceptions may get mapped back into our common error types. - if (isset($this->known_exception_types[$error_type])) { - $error_type = $this->known_exception_types[$error_type]; - } + // Basically, htmlspecialchars it minus &. (for entities!) + $error_message = strtr($error_message, ['<' => '<', '>' => '>', '"' => '"']); - if (empty($tried_hook)) { - $tried_hook = true; + $error_message = strtr($error_message, ['<br />' => '
', '<br>' => '
', '<b>' => '', '</b>' => '', "\n" => '
']); - // Allow the hook to change the error_type and know about the error. - IntegrationHook::call('integrate_error_types', [&$other_error_types, &$error_type, $error_message, $file, $line]); + // Add a file and line to the error message? + // Don't use the actual txt entries for file and line. + // Instead use %1$s for file and %2$s for line. + // Windows style slashes don't play well, lets convert them to the UNIX style. + $file = str_replace('\\', '/', $file); - $this->known_error_types = array_merge($this->known_error_types, $other_error_types); - } + // Find the best path and query string we can... + if (SMF === 'SSI') { + $request_url = ($_SERVER['REQUEST_SCHEME'] ?? 'http') . '://' . ($_SERVER['SERVER_NAME'] ?? 'unknown') . '/' . ltrim($_SERVER['REQUEST_URI'] ?? (($_SERVER['DOCUMENT_URI'] ?? $_SERVER['SCRIPT_NAME'] ?? 'unknown.php') . (!empty($_SERVER['QUERY_STRING']) ? '?' . $_SERVER['QUERY_STRING'] : '')), '/'); + } elseif (str_starts_with(($_SERVER['REQUEST_URL'] ?? ''), Config::$boardurl)) { + $request_url = substr($_SERVER['REQUEST_URL'], \strlen(Config::$boardurl)); + } else { + $request_url = ($_SERVER['REQUEST_URL'] ?? ''); + } - // 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'; + // Don't log the session hash in the url twice, it's a waste. + $request_url = Utils::htmlspecialchars(preg_replace(['~([?&;]sesc)=[^&;]+~', '~' . session_name() . '=' . session_id() . '[&;]~'], ['$1', ''], $request_url)); - // Leave out the call to this method. - array_splice($backtrace, 0, 1); + // Just so we know what board error messages are from. + if (isset($_POST['board']) && !isset($_GET['board']) && SMF !== 'SSI') { + $request_url .= ($request_url == '' ? 'board=' : ';board=') . $_POST['board']; + } - // Never log call arguments or bound objects. - // - // The backtraces we collect ourselves already omit the arguments, but a - // backtrace handed to us by an exception keeps both, and neither is - // safe to encode. Arguments can hold whatever the member submitted, - // including their password, and reading a property of a bound object - // can throw, which would turn an error we were merely logging into an - // uncaught fatal. - foreach ($backtrace as &$frame) { - unset($frame['args'], $frame['object']); - } - unset($frame); + // This prevents us from infinite looping if the hook or call produces an error. + $other_error_types = []; - $backtrace = Utils::jsonEncode($backtrace); + // Exceptions may get mapped back into our common error types. + if (isset($this->known_exception_types[$error_type])) { + $error_type = $this->known_exception_types[$error_type]; + } - // Don't log the same error countless times, as we can get in a cycle of depression... - $error_info = [ - User::$me->id ?? 0, - time(), - User::$me->ip ?? IP::getUserIP(), - $request_url, - $error_message, - (string) (User::$sc ?? ''), - $error_type, - $file, - $line, - $backtrace, - ]; + if (empty($tried_hook)) { + $tried_hook = true; - if (empty($last_error) || $last_error != $error_info) { - $error_batch[] = $error_info; - $last_error = $error_info; + // Allow the hook to change the error_type and know about the error. + IntegrationHook::call('integrate_error_types', [&$other_error_types, &$error_type, $error_message, $file, $line]); - // Get an error count, if necessary - if (!isset(Utils::$context['num_errors'])) { - $query = Db::$db->query( - 'SELECT COUNT(*) - FROM {db_prefix}log_errors', - [], - ); - list(Utils::$context['num_errors']) = Db::$db->fetch_row($query); - Db::$db->free_result($query); - } else { - Utils::$context['num_errors']++; + $this->known_error_types = array_merge($this->known_error_types, $other_error_types); } - // Flush batch when threshold reached. - if (\count($error_batch) >= $batch_size) { - $this->flushErrorBatch($error_batch); - $error_batch = []; + // 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); + + // Never log call arguments or bound objects. + // + // The backtraces we collect ourselves already omit the arguments, but a + // backtrace handed to us by an exception keeps both, and neither is + // safe to encode. Arguments can hold whatever the member submitted, + // including their password, and reading a property of a bound object + // can throw, which would turn an error we were merely logging into an + // uncaught fatal. + foreach ($backtrace as &$frame) { + unset($frame['args'], $frame['object']); } + unset($frame); + + $backtrace = Utils::jsonEncode($backtrace); + + // Don't log the same error countless times, as we can get in a cycle of depression... + $error_info = [ + User::$me->id ?? 0, + time(), + User::$me->ip ?? IP::getUserIP(), + $request_url, + $error_message, + (string) (User::$sc ?? ''), + $error_type, + $file, + $line, + $backtrace, + ]; + + if (empty($last_error) || $last_error != $error_info) { + $error_batch[] = $error_info; + $last_error = $error_info; + + // Get an error count, if necessary + if (!isset(Utils::$context['num_errors'])) { + $query = Db::$db->query( + 'SELECT COUNT(*) + FROM {db_prefix}log_errors', + [], + ); + list(Utils::$context['num_errors']) = Db::$db->fetch_row($query); + Db::$db->free_result($query); + } else { + Utils::$context['num_errors']++; + } - // Register shutdown function to flush remaining batch. - if (!$shutdown_registered) { - register_shutdown_function(function () use (&$error_batch) { - if (!empty($error_batch)) { - $this->flushErrorBatch($error_batch); - } - }); - $shutdown_registered = true; - } - } + // Flush batch when threshold reached. + if (\count($error_batch) >= $batch_size) { + $this->flushErrorBatch($error_batch); + $error_batch = []; + } - // Reset error call - $error_call = 0; + // Register shutdown function to flush remaining batch. + if (!$shutdown_registered) { + register_shutdown_function(function () use (&$error_batch) { + if (!empty($error_batch)) { + $this->flushErrorBatch($error_batch); + } + }); + $shutdown_registered = true; + } + } - // Return the message to make things simpler. - return $error_message; + // Return the message to make things simpler. + return $error_message; + } finally { + // The early return when logging is off, and any error raised on + // the way through, both leave this method without reaching the + // end of it, so the count is balanced here instead. + $error_call--; + } } /** diff --git a/tests/Unit/ErrorHandlerServiceTest.php b/tests/Unit/ErrorHandlerServiceTest.php new file mode 100644 index 0000000000..92f78be350 --- /dev/null +++ b/tests/Unit/ErrorHandlerServiceTest.php @@ -0,0 +1,90 @@ +assertSame('error ' . $i, $service->log('error ' . $i)); + } + } + + public function testTheMessageIsHandedBackUnchangedWhenNothingIsLogged(): void + { + // Callers use the return value to build what they show, as in + // die(ErrorHandler::log($msg)), so it has to come back whether the + // error was recorded or not. + $service = new ErrorHandlerService(); + + $this->assertSame('something went wrong', $service->log('something went wrong')); + } + + /****************** + * Internal methods + ******************/ + + protected function setUp(): void + { + $this->had_setting = isset(Config::$modSettings['enableErrorLogging']); + $this->setting = Config::$modSettings['enableErrorLogging'] ?? null; + + Config::$modSettings['enableErrorLogging'] = false; + } + + /** + * PHPUnit does not reset SMF's statics between tests, so a setting left + * behind here would leak into every test that follows. + */ + protected function tearDown(): void + { + unset(Config::$modSettings['enableErrorLogging']); + + if ($this->had_setting) { + Config::$modSettings['enableErrorLogging'] = $this->setting; + } + } +}