Skip to content

[3.0] Count the errors that are on the stack, not the errors that happened #9606

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
albertlast wants to merge 1 commit into
base: release-3.0
Choose a base branch
from
+216 −119
Open

[3.0] Count the errors that are on the stack, not the errors that happened #9606

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
245 changes: 126 additions & 119 deletions Sources/Services/ErrorHandlerService.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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, ['<' => '&lt;', '>' => '&gt;', '"' => '&quot;']);

$error_message = strtr($error_message, ['&lt;br /&gt;' => '<br>', '&lt;br&gt;' => '<br>', '&lt;b&gt;' => '<strong>', '&lt;/b&gt;' => '</strong>', "\n" => '<br>']);

// 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, ['<' => '&lt;', '>' => '&gt;', '"' => '&quot;']);

if (empty($tried_hook)) {
$tried_hook = true;
$error_message = strtr($error_message, ['&lt;br /&gt;' => '<br>', '&lt;br&gt;' => '<br>', '&lt;b&gt;' => '<strong>', '&lt;/b&gt;' => '</strong>', "\n" => '<br>']);

// 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--;
}
}

/**
Expand Down
90 changes: 90 additions & 0 deletions tests/Unit/ErrorHandlerServiceTest.php
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,90 @@
<?php

declare(strict_types=1);

namespace SMF\Tests\Unit;

use PHPUnit\Framework\Attributes\CoversClass;
use PHPUnit\Framework\TestCase;
use SMF\Config;
use SMF\Services\ErrorHandlerService;

/**
* Covers the re-entrancy guard in SMF\Services\ErrorHandlerService.
*
* Logging an error is allowed to produce one more error, but a third means
* whatever the method depends on is failing every time it is called, so it
* stops rather than going round again. With error logging switched off none
* of that machinery is reached, which keeps this on the near side of the
* database.
*/
#[CoversClass(ErrorHandlerService::class)]
class ErrorHandlerServiceTest extends TestCase
{
/*********************
* Internal properties
*********************/

/**
* @var bool Whether enableErrorLogging was set before the test.
*/
private bool $had_setting = false;

/**
* @var mixed enableErrorLogging as it was before the test.
*/
private mixed $setting = null;

/****************
* Public methods
****************/

public function testErrorsThatAreNotLoggedDoNotCountAsALoop(): void
{
// The guard counts calls that are on the stack, and the count was only
// cleared at the very end of the method. Returning early because
// logging is off skipped that, so the count climbed on every call and
// the third unrelated error in a request died with 'loop detected',
// which in a test run takes the whole process with it.
$service = new ErrorHandlerService();

foreach (range(1, 5) as $i) {
$this->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;
}
}
}