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

[albertlast]

Description

ErrorHandlerService::log() keeps a count so that an error raised while logging an error does not go round for ever. The count is incremented on the way in and was cleared by reaching the end of the method:

$error_call++;
...
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;          // never reaches the reset below
}
...
// Reset error call
$error_call = 0;

That early return skips the reset. With error logging switched off the count therefore climbs on every call and never comes back down, so the third error in a request dies — with a var_dump() of a backtrace and "loop detected" — even though nothing recursed and the three errors had nothing to do with each other.

The count is now balanced in a finally, which covers that return and also the case where something between the two throws. Nothing else changes: the threshold and the message are what they were, and on the path that already worked the count still goes from one back to zero.

Most of the diff is the reindentation for the try. git diff -w is nine lines.

How it turned up

On the Windows job added in #9601. The runner has no fileinfo extension, Utils::getMimeType() logs required_extension_missing when it is absent, Avatar calls it for every gallery avatar, and the third one killed PHPUnit outright:

Error: loop detected. The database may have failed or crashed.
Fatal error: Premature end of PHP process when running
SMF\Tests\Unit\AvatarTest::testAGalleryAvatarInTheRootOfTheGalleryIsFoundToo

The extension is dealt with separately in #9601. This is the other half: three unrelated errors should not be a loop.

It is not specific to tests or to Windows. Any forum with error logging turned off dies on the third logged error of a request, and shows a raw backtrace while doing it. The same shape is in 2.1's log_error(), so it has been there a long while.

Tests

tests/Unit/ErrorHandlerServiceTest.php logs five errors with logging off and asserts each returns its message. With logging off the method returns before it touches the database, so this stays on the near side of the line.

Against the unfixed code it does not merely fail, it reproduces the bug exactly:

Error: loop detected. The database may have failed or crashed.
Fatal error: Premature end of PHP process when running
SMF\Tests\Unit\ErrorHandlerServiceTest::testErrorsThatAreNotLoggedDoNotCountAsALoop

Genuine recursion still ends in the same die(), which cannot be asserted from inside the process that dies, so that path is unchanged and untested.

One thing left alone deliberately: the var_dump($backtrace) before the die() writes paths straight to the response. It is worth removing, but it is a different argument from this one and I did not want to bundle it. Happy to follow up.

Issues References (Fixes|Related|Closes)

1. Related to [3.0][Testing] Run the unit tests on Windows as well as Linux #9601

[albertlast]

in my opinion the bot change many code, dunno if we want this way?

[jdarwood007]

All it looks to be doing is wrapping a try statement around it so it can decrement it. If an error happens while logging an error, we are in a situation that won't recover. If we make it to the return, resetting the count is fine.
Don't think we should fix this.

[live627]

Yeah, but the recursive error case isn't affected by this branch. When error logging is disabled, the three separate errors in one request (three undefined indexes) reportedly trip the loop detection.

[jdarwood007]

Thats because of this code:

SMF/Sources/Services/ErrorHandlerService.php

Lines 231 to 234 in 8d94f6d

	// Check if error logging is actually on.
	if (empty(Config::$modSettings['enableErrorLogging'])) {
	return $error_message;
	}

Its missing the reset of the error level as seen by the main exit

SMF/Sources/Services/ErrorHandlerService.php

Lines 350 to 354 in 8d94f6d

	// Reset error call
	$error_call = 0;
	// Return the message to make things simpler.
	return $error_message;

Adding it there will fix the issue.

[jdarwood007]

Or move the logging disabled up. We can't catch a loop detection if we are not logging.