Skip to content

[3.0] Handle failed prepare statements and oversized data in error logs - #9873

Open
jdarwood007 wants to merge 1 commit into
SimpleMachines:release-3.0from
jdarwood007:3.0/errorLogFixes
Open

jdarwood007 wants to merge 1 commit into
SimpleMachines:release-3.0from
jdarwood007:3.0/errorLogFixes

Conversation

@jdarwood007

Copy link
Copy Markdown
Member

Fixes #7831

@albertlast

Copy link
Copy Markdown
Collaborator

I tested this against an installed forum on both engines, by calling error_insert() with 17 kinds of message under three IPs, both normally and with the prepare forced to fail. I have some concerns:

1. The fallback to insert(). When the statement cannot be prepared, the forum is already in a bad state, and the regular query path may be the very thing that failed. Its own errors are logged by calling error_insert() again. #7831 discussed this, and keeping error logging off the normal insert path was the reason for the prepared statement in the first place.

As written, the fallback also cannot work. It passes $error_array as a single flat row, and insert() rejects that with "Invalid data structure sent to the database" unless $backward_compatibility is on. With the prepare failing, every case on both engines ended in that fatal error.

2. substr() cuts bytes, not characters. A long message cut inside a multibyte character leaves invalid UTF-8, which both engines reject, so the error is lost. A 70 KB message of 3-byte characters was not stored on either engine. A message holding invalid UTF-8 is lost the same way.

3. $db_persist is not defined inside the class. PostgreSQL.php reads empty($db_persist), which is always true there, so pooled connections now get the named statement. It should be $this->persist. With pooling, the unnamed statement also needs preparing every time, because any other query may have replaced it since. Caching it in $this->error_data_prep reuses a statement that may be gone.

normal prepare fails
this PR, MySQL 45 / 51 stored fatal: Invalid data structure
this PR, PostgreSQL 45 / 51 stored fatal: Invalid data structure

I've opened #9882 as an alternative. It keeps to the prepared statement only and returns when the statement cannot be prepared. Before binding, it cleans the values: strings are cut with mb_strcut(), invalid UTF-8 is replaced and NUL bytes are removed. It stores 51/51 on both engines, and the failing-prepare case finishes without an error or a loop.

The loop described in #7831, where the connection dies after the first query, turned out not to be in error_insert() at all. On 3.0 it is the SELECT COUNT(*) that ErrorHandlerService::log() runs before it batches an error. #9884 fixes that.

@albertlast

Copy link
Copy Markdown
Collaborator

I re-ran the same tests against the current head (eefb51a), on MySQL and PostgreSQL. Each message ran in a PHP process of its own, so that the new counter doesn't hide anything.

1. Only the first two errors of a request are logged. static $loop goes up on every call and is never reset, so from the third call on, error_insert() returns without logging. 3.0 writes its batched errors at shutdown through this method, so any request, or any cron run, that has three or more errors loses all but two. Logging five ordinary errors in one process:

MySQL PostgreSQL
release-3.0 5 stored 5 stored
this PR 2 stored 2 stored

2. Every error is lost when the prepare fails. The fallback still passes a single flat row to insert(). With the prepare forced to fail (verified before each run), every one of the 51 messages ended in a fatal "Invalid data structure sent to the database", on both engines.

3. Utils::entitySubstr() counts characters, and the columns are limited in bytes. It cuts to 65534 graphemes, which for 2-, 3- or 4-byte characters is far more than the 65,535 bytes a MySQL TEXT column holds, so the insert fails:

normal mode, 17 messages × 3 IPs MySQL PostgreSQL
stored 42 / 51 51 / 51
lost long 2-byte, 3-byte and emoji messages none

4. Invalid UTF-8 erases the message. grapheme_substr() returns false for invalid UTF-8, and the (string) cast in entitySubstr() turns that into an empty string. The row is stored with an empty message on both engines, so the error text is gone.

#9882 avoids all four: there is no fallback and no counter, strings are cut with mb_strcut() to the column's size in bytes, and invalid bytes are replaced with mb_scrub() rather than dropping the whole string. #9884 (merged) fixed the loop that #7831 reports.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

mysqli_prepare can return false

2 participants