Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-24487

Error after update to 10.5.8 on CentOS-8: DBD::mysql::st execute failed: Unknown MySQL error

Details

    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.

      Attachments

        Issue Links

          Activity

            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?

            elenst Elena Stepanova added a comment - 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?
            andrewponomarenko Andrey P. added a comment - - edited

            $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.

            andrewponomarenko Andrey P. added a comment - - edited $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.
            andrewponomarenko Andrey P. added a comment -

            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).
            

            andrewponomarenko Andrey P. added a comment - 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).
            andrewponomarenko Andrey P. added a comment -

            In mariadb.log:

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

            andrewponomarenko Andrey P. added a comment - In mariadb.log: 2021 - 01 - 13 9 : 26 : 39 71 [Warning] Aborted connection 71 to db: '...' user: '...' host: 'localhost' (Unknown error)
            andrewponomarenko Andrey P. added a comment -

            Same for MariaDB-server-10.5.6.

            andrewponomarenko Andrey P. added a comment - Same for MariaDB-server-10.5.6.
            andrewponomarenko Andrey P. added a comment -

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

            andrewponomarenko Andrey P. added a comment - Can't downgrade to lower versions due to forward incompatibility of the database.

            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?

            elenst Elena Stepanova added a comment - 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?
            andrewponomarenko Andrey P. added a comment -

            Example of failed statement:

            SELECT 1;
            

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

            andrewponomarenko Andrey P. added a comment - Example of failed statement: SELECT 1 ; Any query is failed immediately. And succeeded after restart of service.

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

            And which mysqlclient is this libdbd linked with?

            elenst Elena Stepanova added a comment - If it's the same on 10.5.6, which version did you upgrade from? And which mysqlclient is this libdbd linked with?
            andrewponomarenko Andrey P. added a comment -

            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.

            andrewponomarenko Andrey P. added a comment - 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.

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

            serg Sergei Golubchik added a comment - you can try to install sql_errlog plugin — it might show errors the server gets before disconnecting you.

            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?

            elenst Elena Stepanova added a comment - 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?
            andrewponomarenko Andrey P. added a comment -

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

            andrewponomarenko Andrey P. added a comment - Reproduced this on other node with CentOS-7 and MariaDB 10.6.4.
            andrewponomarenko Andrey P. added a comment -

            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)
            

            andrewponomarenko Andrey P. added a comment - 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)
            andrewponomarenko Andrey P. added a comment -

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

            andrewponomarenko Andrey P. added a comment - I've enabled the sql_errlog plugin. Where I can find the log?

            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/

            serg Sergei Golubchik added a comment - 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/
            andrewponomarenko Andrey P. added a comment -

            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 ...
            

            andrewponomarenko Andrey P. added a comment - 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 ...

            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.

            serg Sergei Golubchik added a comment - It simply means that the client has disconnected or a connection was aborted. May be incorrect packet somewhere. Or a too-short timeout. So: first, check all network-related timeouts, make sure connection isn't simply timing out if it's an incorrect packet, we might be able to fix it based on the captured traffic. with tcpdump or a wireshark 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.

            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.

            monty Michael Widenius added a comment - 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.
            monty Michael Widenius added a comment - - edited

            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.

            monty Michael Widenius added a comment - - edited 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.

            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.

            monty Michael Widenius added a comment - 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.
            monty Michael Widenius added a comment - - edited

            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/ |
            +--------------------------+----------------------

            monty Michael Widenius added a comment - - edited 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/ | +--------------------------+----------------------

            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

            monty Michael Widenius added a comment - 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
            bar Alexander Barkov added a comment - monty , please review a patch: https://github.com/MariaDB/server/commits/bb-10.5-bar-MDEV-24487 Thanks.

            Approved by Monty on slack.

            bar Alexander Barkov added a comment - Approved by Monty on slack.
            andrewponomarenko Andrey P. added a comment -

            Great work, guys! Thanks a lot!

            andrewponomarenko Andrey P. added a comment - Great work, guys! Thanks a lot!

            People

              bar Alexander Barkov
              andrewponomarenko Andrey P.
              Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.