[3.0] Improve ErrorHandlerService error logging performance and diagnostics

[live627]

• Avoid unnecessary backtrace generation when error logging is disabled.
• Detect recursive error handling before collecting the backtrace.
• Remove ErrorHandler frames from logged backtraces. Blindly removing the first entry messed up exception traces.
• Include the exception class in logged exception messages.
• Fix fatalLang() to use the requested language file.
• Batch error records into a single database insert. Oversight from [3.0] Optimize error logging with batching and deferred database writes #9289.

[albertlast]

I ran this branch (6acafc2) on a local forum against current release-3.0 (MySQL) and found two problems. One of them stops errors being logged at all.

1. Nothing reaches log_errors

flushErrorBatch() reads each row by name ($error_array['id_member'] and so on):

SMF/Sources/Services/ErrorHandlerService.php

Lines 807 to 819 in 6acafc2

	foreach ($errors as $error_array) {
	$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'],
	];

But log() still builds each row as a numbered list:

SMF/Sources/Services/ErrorHandlerService.php

Lines 305 to 316 in 6acafc2

	$error_info = [
	User::$me->id ?? 0,
	time(),
	User::$me->ip ?? IP::getUserIP(),
	$request_url,
	$error_message,
	(string) (User::$sc ?? ''),
	$error_type,
	$file,
	$line,
	$backtrace,
	];

error_insert() worked because it runs array_combine() on the list before using it. I called ErrorHandler::log() ten times with different messages, which is enough to hit $batch_size:

	rows written	warnings
release-3.0	10	0
this PR	0	100 × Undefined array key "id_member" … "backtrace"

Either build the row by position here, or give $error_info named keys.

2. The frame filter removes the line that raised the error

In a backtrace frame, class is the class of the method being called, but file/line are where the call was made. So the frame for SMF\ErrorHandler::log() or fatalLang() is the one that holds the caller's own line, and that's exactly the frame this removes:

SMF/Sources/Services/ErrorHandlerService.php

Lines 282 to 287 in 6acafc2

	// Remove any ErrorHandler frames from the backtrace.
	$backtrace = array_filter(
	$backtrace,
	// Intentionally not matching exact class names here.
	static fn(array $trace): bool => !isset($trace['class']) || !str_contains($trace['class'], 'ErrorHandler'),
	);

With the key problem above patched locally, a function that calls ErrorHandler::log() stored this:

release-3.0:  [{"file":"/tmp/probe.php","line":17,"function":"log","class":"SMF\\ErrorHandler","type":"::"},
               {"file":"/tmp/probe.php","line":44,"function":"probe_outer"}]
this PR:      {"2":{"file":"/tmp/probe.php","line":44,"function":"probe_outer"}}

Line 17, the log() call, is gone. fatalLang() passes no file or line to log(), so for those errors the backtrace was the only record of where they came from. array_filter() also keeps the original keys, so the backtrace is now stored as a JSON object instead of a list. The backtrace viewer still shows it, but numbers the frames from 2. Wrapping the result in array_values() fixes the numbering. The lost line needs a different rule, for example dropping only the frames whose file is inside the handler classes.

3. What error_insert() did that insert() doesn't

I ran these on both engines, against release-3.0 and against this branch with problem 1 patched so it didn't hide them.

PostgreSQL loses the queued errors when a query fails inside a transaction. error_insert() rolls back an open transaction before inserting, and insert() doesn't. The drivers open transactions in change_column(), create_table() and drop_table(). I logged one ordinary error, opened a transaction and ran a query that fails:

	rows written
release-3.0	2: the earlier error and the database error
this PR	0

The shutdown flush runs inside the aborted transaction, and insert() skips error handling for log_errors, so nothing reports the failure. The earlier error is lost too, even though it had nothing to do with the transaction.

A request whose REMOTE_ADDR isn't an IP dies at the flush. error_insert() stores an invalid IP as NULL. The inet check in insert() raises a critical error instead. IP::getUserIP() falls back to the raw REMOTE_ADDR without validating it; an empty one comes back as '', which is still stored as NULL. On MySQL, with REMOTE_ADDR set to unix: and ten errors logged:

	result
release-3.0	10 rows, IP NULL, request carries on
this PR	"Error: loop detected" printed twice, request stops, 0 rows

It needs a server that puts something other than an IP in REMOTE_ADDR, so it's rare.

Correction to the first version of this comment: a failed insert does not come back into log(). Both drivers' insert() pass db_error_skip when the table is log_errors. When I made the flush fail with a 300-character file name, neither version died on either engine. On PostgreSQL this branch is actually quieter: release-3.0's pg_execute() raises a warning, which gets logged as an error of its own.

Unrelated to this PR, and already on release-3.0 (seen on both branches): when a query fails inside a PostgreSQL transaction and it's the first error of the request, the request ends with "Error: loop detected" and nothing is logged. log() runs SELECT COUNT(*) FROM log_errors whenever Utils::$context['num_errors'] isn't set, and only the admin error-log page sets it. That count fails in the aborted transaction, so the request dies before the shutdown flush is ever registered.

Smaller points

• catch() puts the exception class in front of the message, and that message is also what fatal() shows the visitor (L182, L188). Guests would see SMF\…\SomeException: …. Adding the class only to the logged copy would avoid that.
• The loop check now runs before the backtrace is collected, so var_dump($backtrace) on L226 usually prints NULL.

A test calling log() ten times and counting the rows in log_errors would catch the first problem, and tests/Integration/ can already do that.

[Sesquipedalian]

Thanks for this, @live627. I had noticed that the back traces were weird, but I hadn't looked into why.

Didn't notice the comments from albertlast

[live627]

I still need to fix the concerns brought forth first before we can merge this.

…

On Mon, Sep 14, 2026 at 8:52 AM Jon Stovell ***@***.***> wrote: ***@***.**** approved this pull request. Thanks for this, @live627 <https://github.com/live627>. I had noticed that the back traces were weird, but I hadn't looked into why. — Reply to this email directly, view it on GitHub <#9689?email_source=notifications&email_token=AADJNNZE4R4QYBKM2LJWYXL5PAH3BA5CNFSNUABKM5UWIORPF5TWS5BNNB2WEL2QOVWGYUTFOF2WK43UKJSXM2LFO4XTKMJZHE4DQMBRGM42M4TFMFZW63VHNVSW45DJN5XKKZLWMVXHJLDGN5XXIZLSL5RWY2LDNM#pullrequestreview-5199880139>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AADJNN6D54672UITJZGTXAT5PAH3BAVCNFSNUABDKJSXA33TNF2G64TZHMZTENJXGQ3TKO2JONZXKZJ3GU2DGOJSHA4DAMZRUF3AE> . Triage notifications, keep track of coding agent tasks and review pull requests on the go with GitHub Mobile for iOS <https://github.com/notifications/mobile/ios/AADJNN6KCEYASLXWEUJIJ7T5PAH3BA5CNFSNUABKM5UWIORPF5TWS5BNNB2WEL2QOVWGYUTFOF2WK43UKJSXM2LFO4XTKMJZHE4DQMBRGM42M4TFMFZW63VHNVSW45DJN5XKKZLWMVXHJKTGN5XXIZLSL5UW64Y> and Android <https://github.com/notifications/mobile/android/AADJNN7RI6FDXOR3J7T57KD5PAH3BA5CNFSNUABKM5UWIORPF5TWS5BNNB2WEL2QOVWGYUTFOF2WK43UKJSXM2LFO4XTKMJZHE4DQMBRGM42M4TFMFZW63VHNVSW45DJN5XKKZLWMVXHJLTGN5XXIZLSL5QW4ZDSN5UWI>. Download it today! You are receiving this because you were mentioned.Message ID: <SimpleMachines/SMF/pull/9689/review/5199880139 ***@***.*** com>

[albertlast]

I ran 6f17ce7 on a local forum, on MySQL and PostgreSQL. Thanks for the fixes: rows reach log_errors again, an invalid IP is stored as NULL, the backtrace is a list, and the exception class only goes to the log. To check the new tests catch the regressions they're for, I put each bug back one at a time. Removing the array_combine() fix fails both tests, and removing array_values() fails assertIsList().

Two new things came up in the tests, and three from my earlier comment are still there.

1. testUndefinedErrors() fails on PostgreSQL

	new test class	whole suite (352 tests)
MySQL	passes	passes
PostgreSQL	fails	only this test fails

Failed asserting that two strings are identical.
-'undefined_vars'
+'undefined_vars '

log_errors.error_type is char(15). PostgreSQL pads the value with spaces when it's read back, and MySQL strips them. The logged row is fine; only the comparison in PHP breaks. rtrim() the value before the assertion:

SMF/tests/Integration/ErrorHandlerServiceTest.php

Line 127 in 6f17ce7

$this->assertSame('undefined_vars', $row['error_type']);

The PR's checks don't show this: the unit test jobs passed, so this integration test most likely skipped there with no forum to run against.

2. testFullBatchIsWrittenToErrorLog() doesn't test the batch size

It still passes with the test's own batch size changed from 2 to 1000:

SMF/tests/Integration/ErrorHandlerServiceTest.php

Line 28 in 6f17ce7

$service->batch_size = 2;

$batch_size is set on each object, but the queued errors live in static $error_batch inside log(), and every object shares that. The second call goes through ErrorHandler::log(), which uses the container's service. Installation.php sets that service's batch size to 1, so it flushes both rows, whatever $service was given. To test a batch of 2 filling up, both calls have to go through the same object, and the test has to set that object's batch size.

3. Still open

• Code standard check fails on the new test file:
  • testUndefinedErrors() starts at column 0 (L100).
  • SMF\Infrastructure\Container is imported and never used.
  • tesstUndefinedErrors() never runs, because its name doesn't start with test (L67).
  • composer lint-fix fixes the formatting, but the leftover method needs deleting by hand.
• The frame filter still removes the line that called ErrorHandler::log() (L288). An error logged from inside a function stores two frames on release-3.0, lines 20 and 110 of my test script. This branch stores only the one at line 110. testUndefinedErrors() doesn't cover this: trigger_error() reaches the handler directly from PHP, so no frame holding the caller's line gets removed. A test calling ErrorHandler::log() from a helper function would.
• PostgreSQL still loses queued errors when a query fails inside a transaction. flushErrorBatch() doesn't roll back first, as error_insert() did. Tested again with one error logged earlier in the request: release-3.0 wrote 2 rows and this branch wrote 0.