MySQL Replication stuck at ‘preparing’

innodbmariadbMySQLreplication

My MariaDB replication stuck at 'preparing'.
This happend after an update and restart of the server yesterday. Since then, replication is not working.

Setup: 2 MariaDB servers with master-master replication. Version: 10.4 (Upgraded few weeks ago from 10.1 – replication has worked after upgrade)

Since the output of both servers for SHOW SLAVE STATUS is similar, i am posting only from my first server:

MariaDB [(none)]> show slave status\G;
*************************** 1. row ***************************
                Slave_IO_State: NULL
                   Master_Host: data2
                   Master_User: replusr
                   Master_Port: 3306
                 Connect_Retry: 60
               Master_Log_File: mariadb-bin.018865
           Read_Master_Log_Pos: 14137515
                Relay_Log_File: relay-bin.017274
                 Relay_Log_Pos: 4
         Relay_Master_Log_File: mariadb-bin.018865
              Slave_IO_Running: Preparing
             Slave_SQL_Running: Yes
               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:
                  Skip_Counter: 0
           Exec_Master_Log_Pos: 14137515
               Relay_Log_Space: 768
               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:
   Replicate_Ignore_Server_Ids:
              Master_Server_Id: 2
                Master_SSL_Crl:
            Master_SSL_Crlpath:
                    Using_Gtid: No
                   Gtid_IO_Pos:
       Replicate_Do_Domain_Ids:
   Replicate_Ignore_Domain_Ids:
                 Parallel_Mode: conservative
                     SQL_Delay: 0
           SQL_Remaining_Delay: NULL
       Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it
              Slave_DDL_Groups: 0
Slave_Non_Transactional_Groups: 0
    Slave_Transactional_Groups: 0
1 row in set (0.000 sec)

ERROR: No query specified

Logs aren't showing anything and binaries are exploding since they cannot be rotated because the replication won't continue.

I've never seen something like that. Any ideas?

EDIT – How to downgrade to previous version:
This seems to be a bigger problem. See: https://downloads.mariadb.org/mariadb/10.4.6/

For all the others who have the same problem, follow these steps to downgrade (I'll give an example for 10.4.6, since this was my case):
Find the version you have used before and the related source: https://downloads.mariadb.org/mariadb/10.4.6/

After that, add it to your /etc/apt/sources.list:

deb [arch=amd64,ppc64el,arm64] http://mirrors.n-ix.net/mariadb/mariadb-10.4.6/repo/ubuntu/ xenial main

Downgrade:

apt install mariadb-server=1:10.4.6+maria~xenial mariadb-server-10.4=1:10.4.6+maria~xenial mariadb-client=1:10.4.6+maria~xenial mariadb-client-10.4=1:10.4.6+maria~xenial mariadb-server-core-10.4=1:10.4.6+maria~xenial mariadb-client-core-10.4=1:10.4.6+maria~xenial mysql-common=1:10.4.6+maria~xenial mariadb-client=1:10.4.6+maria~xenial libmariadb3=1:10.4.6+maria~xenial

Hold packages from upgrade, until fix is published:

apt-mark hold mariadb-server*

The steps are also explained here: https://jira.mariadb.org/browse/MDEV-20247?focusedCommentId=132114&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-132114

Best Answer

I also had the same issue using Mariadb 10.4 master-slave replication. I was using the setting innodb_thread_concurrency in the config file with a non-zero value. I updated it to:

innodb_thread_concurrency = 0

And now it's working again.

I have very bad news for you.

You should not have deleted the ibdata1 file. Here is why:

ibdata1 contains four type of information:

table metadata
MVCC data
data pages (with innodb_file_per_table enabled)
index pages (with innodb_file_per_table enabled)

Each InnoDB table created has a numercial id assigned to it via some auto increment metadata feature to each ibd file. That internal tablespace id (ITSID) is embedded in the .ibd file. That number is checked against the list of ITSIDs maintained, guess where, ... ibdata1.

I also have very good news for you along with some bad news.

It is possible to reconstruct ibdata1 to have the correct ITSIDs but it takes work to do it. While I personally have not done procedure alone, I assisted a client at my employer's web hosting to do this. We figured this out together but since the client hosed ibdata1, I let him do most of the work (30 InnoDB tables).

Anyway, here a past post I made in the DBA StackExchange. I answered another question whose root cause was the mixing up of ITSIDs.

To cut right to the chase, here is the article explaining what to do with reference to ITSID and how to massage ibdata1 into acknowledging the presence of the ITSID contained within the .ibd file.

I am sorry there is no quick-and-dirty method for recovering the .ibd file other than playing games with ITSIDs.

UPDATE 2011-10-17 06:19 EDT

Here is your original innodb configuration from your question:

innodb_file_per_table=1
innodb_flush_method=O_DIRECT
innodb_log_file_size=1G
innodb_buffer_pool_size=4G
innodb_data_file_path=ibdata1:10M:autoextend
innodb_buffer_pool_size = 384M
innodb_log_file_size=5M
innodb_lock_wait_timeout = 18000

Please notice that innodb_log_file_size is there twice. Look carefully...

innodb_file_per_table=1
innodb_flush_method=O_DIRECT
innodb_log_file_size=1G <----
innodb_buffer_pool_size=4G
innodb_data_file_path=ibdata1:10M:autoextend
innodb_buffer_pool_size = 384M
innodb_log_file_size=5M <----
innodb_lock_wait_timeout = 18000

The last setting of innodb_log_file_size takes precedence. MySQL expected to start up with the log files being 5M. Your ib_logfile0 and ib_logfile1 were 1G when you tried to start up mysqld. It saw a size conflict and took the path of least resistance, which was to disable InnoDB. That's why InnoDB was missing from show engines;. Mystery solved !!!

UPDATE 2011-10-17 11:07 EDT

The error message was deceptive because innodb_log_file_size was smaller than the log files (ib_logfile0 and ib_logfile1), which were 1G at the time. What's interesting is this: Corruption was reported because the file was expected to be 5M and the files were bigger. If the situation were reversed and the innodb log files were smaller than the declared size in my.cnf you should get something like this in the error log:

110216 9:48:41 InnoDB: Initializing buffer pool, size = 128.0M
110216 9:48:41 InnoDB: Completed initialization of buffer pool
InnoDB: Error: log file ./ib_logfile0 is of different size 0 5242880 bytes
InnoDB: than specified in the .cnf file 0 33554432 bytes!
110216 9:48:41 [ERROR] Plugin 'InnoDB' init function returned error.
110216 9:48:41 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.

In this example, the log files were already existing as 5M and the setting for innodb_log_file_size was bigger (in this case, 32M).

For this particular question, I blame MySQL (eh Oracle [still hate saying it]) for the inconsistent error message protocol.

MySQL 5.6 – GTID Replication Slave Stuck with System Lock

Since I see more than 2 system user entries in the processlist, I would assume you are using Multi-Threaded Replication (slave_parallel_workers > 1).

That looks like a bug

On Oct 29, 2014, this was expressed by David Moss

Thank you for your feedback. This issue was covered in bug 17326020 and the following was added to the MySQL 5.6.21 and 5.7.5 changelogs:

When the I/O thread reconnected to a master using GTIDs and multithreaded slaves while in the middle of a transaction, it failed to abort the transaction, leaving a partial transaction in the relay log, and then retrieving the same transaction again. This occurred when performing a rotation of the relay log. Now when reconnecting, the server checks before rotating the log in such cases, and waits first for any ongoing transaction to complete.

Therefore nothing new will be added to cover this bug and I'm closing it as fixed.

On Dec 10, 2014, this was expressed by Laurynas Biveinis

Problem:

With MTS, GTIDs and auto positioning enabled, when a worker applies a partial transaction left on relaylog by an IO thread reconnection, it will wait for the XID log event to commit the transaction.

Unfortunately, the SQL thread coordinator will reach the master's ROTATE event on the next relaylog file and will wait for all workers to finish their tasks before applying the ROTATE.

Analysis:

As the whole transaction is retrieved again by the IO thread after the reconnection, the slave must rollback the partial transaction once noticing this ROTATE from the master.

This bug reports the same issue already fixed by BUG#17326020, and the reported issue is not reproducible anymore. So, this patch is just adding a new test case.

SUGGESTION

Run FLUSH BINARY LOGS; on the Master

See if the movement triggers a response from the SQL threads.

If it does not, go ahead and remove slave_parallel_workers from my.cnf and restart mysql.

Since you started MySQL up and master and slave and got error 1236, that means you are trying to establish replication from an impossible position. In the context of GTID and error message you got, the binary logs needed to fully identify a set of queries within a GTID set no longer exists,

Look back at your SHOW SLAVE STATUS\G

Retrieved_Gtid_Set: 7846a847-62c7-11e5-91a6-e06995de432e:4757140-5030085
 Executed_Gtid_Set: 7846a847-62c7-11e5-91a6-e06995de432e:1-4783274

From this, the last GTID executed is 7846a847-62c7-11e5-91a6-e06995de432e:4783274

This means that the binary log that has or had 7846a847-62c7-11e5-91a6-e06995de432e:4783275 no longer exists.

I can see this happening if you stopped replication on the Slave, left replication off long enough for the Master to rotate its binary logs (via expire_logs_days) the slave still needed to see, then turned on replication.

In your particular case, try doing a mysqlbinlog dump of the binary log mysqld-bin.000141. If nothing comes out of it, you will have to reload the Slave and setup replication from scratch.