[MDEV-24487] Error after update to 10.5.8 on CentOS-8: DBD::mysql::st execute failed: Unknown MySQL error Created: 2020-12-24  Updated: 2022-04-01  Resolved: 2022-01-28

Status: Closed
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.5.8
Fix Version/s: 10.5.14, 10.6.6, 10.7.2, 10.8.1

Type: Bug Priority: Critical
Reporter: Andrey P. Assignee: Alexander Barkov
Resolution: Fixed Votes: 0
Labels: None
Environment:

CentOS-8, amd64


Issue Links:
Relates
relates to MDEV-17832 Protocol: extensions for Pluggable ty... Closed

 Description   

Error after update to 10.5.8 on CentOS-8:

DBD::mysql::st execute failed: Unknown MySQL error

By perl-DBI-1.641-3.module_el8.1.0+199+8f0a6bbd.x86_64:

$DBh = DBI->connect("DBI:mysql:$DBName:$DBHost:$DBPort", $DBUser, $DBPasswd, {"mysql_enable_utf8" => 1});

Restart of MariaDB service fixes the issue for a few minutes and it reappears.

Please investigate ASAP.

Now I see same update for my CentOS-7 servers and I'm afraid to install it.



 Comments   
Comment by Elena Stepanova [ 2021-01-12 ]

What does it execute when it fails and before that?
Please provide the exact set of commands you run. You can obfuscate the data if it's confidential, but we need to see both Perl commands and SQL statements.
What does the server error log say?

Comment by Andrey P. [ 2021-01-13 ]

$STh = $DBh->prepare("SELECT * FROM tbl0");
$STh->execute();
while(my $Result = $STh->fetchrow_hashref())
{
    # ...
}

DBD::mysql::st execute failed: Unknown MySQL error at script.pl line 674.
DBD::mysql::st fetchrow_hashref failed: fetch() without execute() at script.pl line 675.

execute() is at 674 line, fetchrow_hashref() is at 675.

Comment by Andrey P. [ 2021-01-13 ]

In systemctl status:

Jan 13 09:18:12 ... mariadbd[257381]: 2021-01-13  9:18:12 6487 [Warning] Aborted connection 6487 to db: '...' user: '...' host: 'localhost' (Got an error writing communication packets).

Comment by Andrey P. [ 2021-01-13 ]

In mariadb.log:

2021-01-13  9:26:39 71 [Warning] Aborted connection 71 to db: '...' user: '...' host: 'localhost' (Unknown error)

Comment by Andrey P. [ 2021-01-13 ]

Same for MariaDB-server-10.5.6.

Comment by Andrey P. [ 2021-01-13 ]

Can't downgrade to lower versions due to forward incompatibility of the database.

Comment by Elena Stepanova [ 2021-01-13 ]

So, DBI->connect succeeds, then the connection executes some statements successfully, then some statement execution fails and at the same time the log reports connection abort?
Is it always the same select that fails, or is it any random statement at any random time?
Does the same statement ever succeed?
When it fails, does it fail immediately or does it hang for a long time before returning the error?

Comment by Andrey P. [ 2021-01-13 ]

Example of failed statement:

SELECT 1;

Any query is failed immediately. And succeeded after restart of service.

Comment by Elena Stepanova [ 2021-03-28 ]

If it's the same on 10.5.6, which version did you upgrade from?

And which mysqlclient is this libdbd linked with?

Comment by Andrey P. [ 2021-03-30 ]

It was 10.5.5.

/usr/lib64/dbd/libdbdmysql.so is not installed in my system (perl-DBI package is used instead).

But, again, simple query from the mariadb shell `SELECT 1` doesn't work.

Comment by Sergei Golubchik [ 2021-07-16 ]

you can try to install sql_errlog plugin — it might show errors the server gets before disconnecting you.

Comment by Elena Stepanova [ 2021-08-18 ]

you can try to install sql_errlog plugin — it might show errors the server gets before disconnecting you.

andrewponomarenko, would you be able to do this?

Comment by Andrey P. [ 2021-10-25 ]

Reproduced this on other node with CentOS-7 and MariaDB 10.6.4.

Comment by Andrey P. [ 2021-10-25 ]

Version: '10.6.4-MariaDB'  socket: '/var/lib/mysql/mysql.sock'  port: 0  MariaDB Server
2021-10-25 22:37:40 33 [Warning] Aborted connection 33 to db: '...' user: '...' host: 'localhost' (Unknown error)

Comment by Andrey P. [ 2021-10-25 ]

I've enabled the sql_errlog plugin. Where I can find the log?

Comment by Sergei Golubchik [ 2021-10-26 ]

By default, I believe, the log file name is sql_errors.log and it's in the datadir. See https://mariadb.com/kb/en/sql-error-log-plugin/

Comment by Andrey P. [ 2021-11-12 ]

It's /var/lib/mysql/sql_errors.log in my case.

The log is the following:

2021-10-25 22:41:57 p119124_s4w[p119124_s4w] @ localhost [] ERROR 1160: Got an error writing communication packets : SELECT * FROM ...

Comment by Sergei Golubchik [ 2022-01-17 ]

It simply means that the client has disconnected or a connection was aborted.
May be incorrect packet somewhere. Or a too-short timeout. So:

  1. first, check all network-related timeouts, make sure connection isn't simply timing out
  2. if it's an incorrect packet, we might be able to fix it based on the captured traffic. with tcpdump or a wireshark
  3. in any case we definitely will be able to fix it, if we'll get a repeatable test case. e.g. a perl script to run that reproduces this error.

these three are in the order of easy-to-complex, I suspect a test case might be difficult to create, but checking timeouts could be done with little efforts.

Comment by Michael Widenius [ 2022-01-26 ]

I have worked with another uses who has exactly the same problem

This happens with a 10.6.5 when connecting with a 10.6 client. 10.5 clients (without extended METADATA) seams to work fine.

I have examined the TCP/IP packets and what happens is that the server switches from using METADATA extended packets to the old format after a few queries.

I suspect we may have random memory write that destroys the client capability flag in the server; I originally suspected we had some code that would forget it, but after checking all code that sets/changes this variable, I could not find anything wrong.

Comment by Michael Widenius [ 2022-01-26 ]

The user just reported that they now got an incident that where using libmariadbclient18/oldoldstable,now 10.1.48-0+deb9u2 (without metadata support) started to get packets with meta data information from a 10.6 server!

There is a clear indication that we have something that causes 'random' changes of thd->client_capabilities in the server 10.6 and apparently also in the 10.5 server, as seen by the original bug report.

Comment by Michael Widenius [ 2022-01-26 ]

This happens also on connections that connects and does one simple select query (nothing else). The first result response will have a packet without metadata even if the client and server both supports metadata.

Comment by Michael Widenius [ 2022-01-26 ]

The user informed me that changing a table used in the SELECT to use utf8mb4 instead of utf8mb3 caused the problem to disappear for a while (worked for a few days)

The user has the following character sets active:
The user have

show variables like "character%";
+--------------------------+----------------------+
| Variable_name            | Value                |
+--------------------------+----------------------+
| character_set_client     | utf8mb3              |
| character_set_connection | utf8mb3              |
| character_set_database   | latin1               |
| character_set_filesystem | binary               |
| character_set_results    | utf8mb3              |
| character_set_server     | utf8mb4              |
| character_set_system     | utf8mb3              |
| character_sets_dir       | /usr/share/charsets/ |
+--------------------------+----------------------

Comment by Michael Widenius [ 2022-01-26 ]

I found the issue:
The user was connecting to MariaDB 10.6 from old and new clients (some that supports EXTENDED_METADATA and some that didn't).
The QUERY_CACHE was on and the query and response was cached.
If now a user with a different value for EXTENDED_METADATA executed the same query, the old response where sent to the user, but this is wrong as the packet is different in this case.

Temporary workaround for anyone having this problem:
set have_query_cache=NO

Fix for the server:
Store the EXTENDED_METADATA flag in the query cache and compare this before sending the result back to the client

Comment by Alexander Barkov [ 2022-01-27 ]

monty, please review a patch:

https://github.com/MariaDB/server/commits/bb-10.5-bar-MDEV-24487

Thanks.

Comment by Alexander Barkov [ 2022-01-28 ]

Approved by Monty on slack.

Comment by Andrey P. [ 2022-04-01 ]

Great work, guys! Thanks a lot!

Generated at Thu Feb 08 09:30:21 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.