Ubuntu 5.5.31-MariaDB-1~lucid-log and 5.5.32-MariaDB-1~precise-log

The error says that the DROP DATABASE failed on the master, with the error "Cannot load from mysql.%s. The table is probably corrupted". Which happens if a stored routine or an event cannot be loaded, because the corresponding table is corrupted or has the wrong structure. Make sure all your mysql.* tables on master2 are not corrupted and properly upgraded (with mysql_upgrade).

Exactly the problem - the drop database command did not fail on the master but the slave thinks it did.

This is what happens when I run the same command on the master:

mysql> DROP DATABASE IF EXISTS temp_vstreams;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> show warnings;
----------------------------------------------------------------------

----------------------------------------------------------------------

----------------------------------------------------------------------
1 row in set (0.00 sec)

Hi,

When replication aborted, it also said which position of which binary log it stopped at. Could you please provide the binary log and the record from the error log?

Thanks.

Because this has been going on for a while the slave is stuck at a bin-log which was expired off of the master a while ago. But I think I can recreate this with a new log file - but it might take me a couple of days.

This is the full show slave status\G message from the slave - please confirm that you want the binary log file 'mariadb-bin.004352' from the master 'masterdb2.staging.ooyala.com' as it is currently about 4 hours behind and a lot of data has changed since.

Also there are no errors in either the master or slave error logs.

MariaDB [(none)]> show slave status\G

*************************** 1. row ***************************

               Slave_IO_State: Waiting for master to send event

                  Master_Host: masterdb2.staging.ooyala.com

                  Master_User: repl

                  Master_Port: 3306

                Connect_Retry: 60

              Master_Log_File: mariadb-bin.004467

          Read_Master_Log_Pos: 47034749

               Relay_Log_File: mysqld-relay-bin.000528

                Relay_Log_Pos: 16760340

        Relay_Master_Log_File: mariadb-bin.004352

             Slave_IO_Running: Yes

            Slave_SQL_Running: No

              Replicate_Do_DB:

          Replicate_Ignore_DB:

           Replicate_Do_Table:

       Replicate_Ignore_Table:

      Replicate_Wild_Do_Table:

  Replicate_Wild_Ignore_Table:

                   Last_Errno: 0

                   Last_Error: Query caused different errors on master and slave.     Error on master: message (format)='Cannot load from mysql.%s. The table is probably corrupted' error code=1548 ; Error on slave: actual message='no error', error code=0. Default database: 'temp_ivideos'. Query: 'DROP DATABASE IF EXISTS temp_ivideos'

                 Skip_Counter: 0

          Exec_Master_Log_Pos: 16760054

              Relay_Log_Space: 12166516532

              Until_Condition: None

               Until_Log_File:

                Until_Log_Pos: 0

           Master_SSL_Allowed: No

           Master_SSL_CA_File:

           Master_SSL_CA_Path:

              Master_SSL_Cert:

            Master_SSL_Cipher:

               Master_SSL_Key:

        Seconds_Behind_Master: NULL

Master_SSL_Verify_Server_Cert: No

                Last_IO_Errno: 0

                Last_IO_Error:

               Last_SQL_Errno: 0

               Last_SQL_Error: Query caused different errors on master and slave.     Error on master: message (format)='Cannot load from mysql.%s. The table is probably corrupted' error code=1548 ; Error on slave: actual message='no error', error code=0. Default database: 'temp_ivideos'. Query: 'DROP DATABASE IF EXISTS temp_ivideos'

  Replicate_Ignore_Server_Ids:

             Master_Server_Id: 1719928223

1 row in set (0.00 sec)

That's right, please upload the binary log mariadb-bin.004352. If it's very big or contains some sensitive data, you can instead parse it yourself with mysqlbinlog, find the position 16760054 in the log and copy-paste several events before and after this position.
Please also include the error log file from the master.

Thanks.

As I understand, it's not really MariaDB-Galera server that you use, right?

Correct - this is just the standard MariaDB not Galera.

But in preparing the files to send to you I have resolved the issue. I still believe there is a bug which can be fixed (perhaps through a better message). What was happening was DROP DATABASE on the master was not causing any errors (the error log is empty) but it was generating 2 warnings - these broke replication on the slave.

use fmf_temp;
Database changed
drop database if exists fmf_temp;
Query OK, 1 row affected (0.00 sec)

Database changed
Query OK, 0 rows affected, 2 warnings (0.00 sec)

MariaDB [(none)]> show warnings;
-----------------------------------------------------------------------

-----------------------------------------------------------------------

-----------------------------------------------------------------------

We never saw any warnings because the statement was run on masterdb1 (which had no warnings) then replicated to masterdb2 (where it would generate a warning but never show it to anyone) then replicated to slavedb2 (where it broke replication because the error messages were different).

running mysql_upgrade --force (needed because it said it was already upgraded to 5.5.32-MariaDB) did fix the issue because now there were no warnings on masterdb2.

I'm not sure how you'd like to proceed - the issues is resolved for me. The bug is there is a statement that will break replication but it is not being logged anywhere making it difficult to track down.

Hi Frank,

> use fmf_temp;
> Database changed
> drop database if exists fmf_temp;
> Query OK, 1 row affected (0.00 sec)
>
> Database changed
> Query OK, 0 rows affected, 2 warnings (0.00 sec)

Could you please comment on this fragment?

So, first you switched to fmf_temp, the response was "Database changed". That's expected.
Then, you did "drop database if exists fmf_temp". The response was "Query OK", no warnings. That's good.
But then, we see two other responses without any queries:

Database changed
Query OK, 0 rows affected, 2 warnings (0.00 sec)

Where do they come from? What were you executing here?

Thanks.

Not exactly - since this is a script I ran three commands on the same line and got the results for all commands in one block - I should have written it like this:

MariaDB [(none)]>create database fmf_temp;
Query OK, 1 row affected (0.00 sec)

MariaDB [(none)]>use fmf_temp;
Database changed

MariaDB [(fmf_temp)]> drop database if exists fmf_temp;
Query OK, 0 rows affected, 2 warnings (0.00 sec)

MariaDB [(none)]> show warnings;
-----------------------------------------------------------------------

-----------------------------------------------------------------------

-----------------------------------------------------------------------

The issues being that the masterdb2 had not have mysqlupgrade run on it (at least running mysqlupgrade on masterdb2 solved the issue) and the bigger issue was that since masterdb1 ran this with no warnings and replicated to to masterdb2 where the warnings did happen shouldn't masterdb2 have stopped replication saying the commands produced different errors? Instead masterdb2 ran these commands and produced warnings (which no one saw because it was the replication thread - they were not written to the error log either) then slavedb2 got the command and ran it with no warnings and broke because it's errors / warnings were different (none) than masterdb2.

Trivial for me to fix - difficult to find.

Thanks Frank,
It's much clearer now.

I'd say there's definitely a bug here. The bug is in the confusion between errors and warnings of level "error".

When the server executes the DROP, it considers it successful, but generates warnings.
However, when the master writes the event into the binary log, it adds the error code of one of the warnings (I guess because of the level "error").
The slave, in turn, also considers DROP successful, although it produces warnings as well. But it compares the non-zero error code which it reads from the binary log only with its own zero error code; it does not take into account the warnings it just generated.

Thus, replication failure is caused by the asymmetry between master and slave behavior. Either the master shouldn't write the error code into the binary log when it's actually a code of a warning, or the slave should compare the master error code from the binary log not only to its own query error code, but also to warning codes.

It works exactly the same way on MySQL (checked 5.5, 5.6, 5.7). You might want to file a bug report at bugs.mysql.com as well.

Here is also serg's quick analysis:

<serg> with DROP there's an error when trying to drop SPs
<serg> and later the error flag is cleared, because the DB and tables in it were, in fact, dropped. So the DROP operation itself was successful.
<serg> it's not push_warning(), but my_error() - real error generating function
<serg> and later thd->clear_error()
<serg> the bug, I think, is that
<serg> this code calls thd->clear_error() but only after writing a query to binlog
<serg> which, indeed, looks plain wrong