Details
-
Type:
Task
-
Status: Closed
-
Priority:
Major
-
Resolution: Duplicate
-
Fix Version/s: 10.0.16
-
Component/s: Replication
-
Labels:
Description
Given the show slave status:
Master_Log_File: mysql-bin.006189
Read_Master_Log_Pos: 70373742
Relay_Log_File: mysqld-relay-bin.001150
Relay_Log_Pos: 94786159
Relay_Master_Log_File: mysql-bin.006189
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: 1213
Last_Error: Deadlock found when trying to get lock; try restarting transaction
Skip_Counter: 0
Exec_Master_Log_Pos: 94785872
Relay_Log_Space: 8290885186
start slave
ls -al mysqld-relay-bin.001150
-rw-rw---- 1 mysql mysql 104600980 Dec 19 09:50 mysqld-relay-bin.001150
Master_Log_File: mysql-bin.006189
Read_Master_Log_Pos: 70715093
Relay_Log_File: mysqld-relay-bin.001150
Relay_Log_Pos: 94786159
Relay_Master_Log_File: mysql-bin.006189
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: 1594
Last_Error: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted (you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted (you can check this by running 'mysqlbinlog' on the relay log), a network problem, or a bug in the master's or slave's MySQL code. If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave.
Skip_Counter: 0
Exec_Master_Log_Pos: 94785872
Relay_Log_Space: 8291226537
mysqlbinlog --base64-output=DECODE-ROWS --start-position 94786159 mysqld-relay-bin.001150 | more
ERROR: Error in Log_event::read_log_event(): 'read error', data_len: 842218041, event_type: 45
ERROR: Could not read entry at offset 94786159: Error in log format or read error.
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
Obviously 94786159 isn't a start position
Looking for what real positions exist in the binlog:
mysqlbinlog mysqld-relay-bin.001150 | grep "^# at 9478[0-9][0-9][0-9][0-9]" | tee /tmp/pos.txt at 94785793 at 94785831 at 94786200 at 94786227 at 94786265
so 94786159 is a wrong position number. looking at prev transaction pos 94785831
mysqlbinlog --start-position 94785831 mysqld-relay-bin.001150 | more
/*!50530 SET @SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @session.max_insert_delayed_threads=0*/;
/*!50003 SET OLD_COMPLETION_TYPE=@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
at 4
#141219 6:25:05 server id 12025 end_log_pos 248 Start: binlog v 4, server v 10.0.15-MariaDB-1~wheezy-log created 141219 6:25:05
BINLOG '
wcSTVA/5LgAA9AAAAPgAAAAAAAQAMTAuMC4xNS1NYXJpYURCLTF+d2hlZXp5LWxvZwAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAA3AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQApm6oDg==
'/*!*/;
at 248
#141219 6:25:02 server id 12022 end_log_pos 0 Start: binlog v 4, server v 10.0.15-MariaDB-1~wheezy-log created 141219 6:25:02
BINLOG '
vsSTVA/2LgAA9AAAAAAAAAAgAAQAMTAuMC4xNS1NYXJpYURCLTF+d2hlZXp5LWxvZwAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAA3AAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQAhzJdFw==
'/*!*/;
at 94785831
#141219 9:32:45 server id 12022 end_log_pos 95042978 Query thread_id=16552077 exec_time=0 error_code=0
use `gemrock_auctions`/*!*/;
SET TIMESTAMP=1418981565/*!*/;
SET @session.pseudo_thread_id=16552077/*!*/;
SET @session.foreign_key_checks=1, @session.sql_auto_is_null=0, @session.unique_checks=1, @session.autocommit=1/*!*/;
SET @session.sql_mode=1073741824/*!*/;
SET @session.auto_increment_increment=2, @session.auto_increment_offset=2/*!*/;
/*!\C utf8 //!*/;
SET @session.character_set_client=33,@session.collation_connection=33,@session.collation_server=192/*!*/;
SET @session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
INSERT INTO `opalauctions_com`.`sessions` (`id`, `ip_address`, `user_agent`, `data`, `date_added`, `date_updated`) VALUES ('571ald9j87ruqumntllvciddh1', '178.154.206.250', 'Mozilla/5.0 (compatible;
YandexBot/3.0; +http://yandex.com/bots)', '', '2014-12-19 09:32:45', '2014-12-19 09:32:45')
/*!*/;
at 94786200
#141219 9:32:45 server id 12022 end_log_pos 95043005 Xid = 171836529
COMMIT/*!*/;
at 94786227
MariaDB [(none)]> select * from opalauctions_com.`sessions` where id='571ald9j87ruqumntllvciddh1';
Empty set (0.02 sec)
So lets start at this position.
change master to Relay_Log_File='mysqld-relay-bin.001150',relay_log_pos=94785831; start slave;
Slave_IO_State:
Master_Host: 192.168.179.103
Master_User: replication
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.006189
Read_Master_Log_Pos: 96248700
Relay_Log_File: mysqld-relay-bin.001150
Relay_Log_Pos: 94785831
Hit MDEV-7395 but otherwise replication continued.
MariaDB [(none)]> set global slave_parallel_threads=0; start slave;
(yes I'd had enough of hitting bugs)
...
MariaDB [(none)]> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 192.168.179.103
Master_User: replication
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.006189
Read_Master_Log_Pos: 100171990
Relay_Log_File: mysqld-relay-bin.001152
Relay_Log_Pos: 4098842
Relay_Master_Log_File: mysql-bin.006108
Slave_IO_Running: Yes
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: 4098555
Relay_Log_Space: 8121038882
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: 932657
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: 12022
Master_SSL_Crl:
Master_SSL_Crlpath:
Using_Gtid: No
Gtid_IO_Pos:
Gliffy Diagrams
Attachments
Activity
- All
- Comments
- Work Log
- History
- Activity
- Transitions
Like MDEV-7395, this looks like a likely duplicate of MDEV-7237. So closing as
a duplicate, when 10.0.16 is released and if it does not fix things, feel free
to re-open with additional info.
Note that the effect of MDEV-7395 is to get the incorrect relay log
file_name. So adjusting the position to a nearby event still gets a
completely wrong position, off by an entire relay log file. So follow-up
errors are likely to result from this.
(I am curious how you got the Last SQL error to be a deadlock error in the
first place. Such errors are supposed to be retried automatically. Did you
run with slave_transaction_retries=0? Or did a transaction really get
deadlocked 10 times in a row (the default value of slave_transaction_retries),
and then give up?)
> Note that the effect of MDEV-7395 is to get the incorrect relay log
file_name. So adjusting the position to a nearby event still gets a
completely wrong position, off by an entire relay log file. So follow-up
errors are likely to result from this
Ok. Was planning a table check at some stage anyway.
> I am curious how you got the Last SQL error to be a deadlock error in the
first place. Such errors are supposed to be retried automatically. Did you
run with slave_transaction_retries=0?
no.
> Or did a transaction really get
deadlocked 10 times in a row (the default value of slave_transaction_retries),
and then give up?
Must of. Its still set to the default of 10. As I assume there is no current status variable to tell me I've added this to MDEV-7340 max consecutive parallel deadlocks.
Getting some reviews and perhaps commits on patches like MDEV-7202, MDEV-7198, MDEV-6981 might make me more confident to add other patches to include basic status monitoring capabilities of what is really a significant improvement in mariadb functionality.
10.0.15 x86_64 mean to be bug not task. bah...