【讨论中】5.5.25a-log 复制遇到的一个奇怪问题

ayalastrike

机器是1 master 2 slave，之前slave 2挂掉，我从slave 1上mysqldump出来数据，导入slave2

导入数据完成后，slave 2从dump的时间点重新进行同步复制，这时出现问题，并且只是s_user_logo这个表的数据报错
具体错误如下

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 192.168.56.119
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000090
          Read_Master_Log_Pos: 246003112
               Relay_Log_File: relay-bin.000002
                Relay_Log_Pos: 267860420
        Relay_Master_Log_File: mysql-bin.000087
             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: 1032
                   Last_Error: Could not execute Update_rows event on table kx_info.s_user_logo_7; Can't find record in 's_user_logo_7', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log mysql-bin.000087, end_log_pos 747388250
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 747387897
              Relay_Log_Space: 2987705016
              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: 1032
               Last_SQL_Error: Could not execute Update_rows event on table kx_info.s_user_logo_7; Can't find record in 's_user_logo_7', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log mysql-bin.000087, end_log_pos 747388250
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 561193306

在master上查看出问题的binlog /usr/local/mysql/bin/mysqlbinlog mysql-bin.000087 -vv --start-position=747387897 | less
# at 747387968
# at 747388042
#121009  6:45:57 server id 561193306  end_log_pos 747388042     Table_map: `kx_info`.`s_user_logo_7` mapped to number 253
#121009  6:45:57 server id 561193306  end_log_pos 747388250     Update_rows: table id 253 flags: STMT_END_F

BINLOG '
pVdzUBNaIXMhSgAAAIo8jCwAAP0AAAAAAAEAB2t4X2luZm8ADXNfdXNlcl9sb2dvXzcADgMDAwMD
AwQDDwMHBwMPBQQKACAAAAA=
pVdzUBhaIXMh0AAAAFo9jCwAAP0AAAAAAAEADv////8AwIeRFQNgUH01yQAAAC8AAAAAAAAAtAAA
AGZauT5RAQAABGpwZWdYAgAAHANzUBwDc1AAAAAAIDFjMWZhNTdiYWQ4ZjJmZDJlYjUyOWZlNWU0
YWE5ZjM1AMCHkRUDYFB9NckAAAAvAAAAAAAAALQAAABmWrk+UQEAAARqcGVnWAIAABwDc1ClV3NQ
AQAAACAxYzFmYTU3YmFkOGYyZmQyZWI1MjlmZTVlNGFhOWYzNQ==
'/*!*/;
### UPDATE kx_info.s_user_logo_7
### WHERE
###   @1=51745159 /* INT meta=0 nullable=0 is_null=0 */
###   @2=897405024 /* INT meta=0 nullable=0 is_null=0 */
###   @3=201 /* INT meta=0 nullable=0 is_null=0 */
###   @4=47 /* INT meta=0 nullable=0 is_null=0 */
###   @5=0 /* INT meta=0 nullable=0 is_null=0 */
###   @6=180 /* INT meta=0 nullable=0 is_null=0 */
###   @7=0.362018             /* FLOAT meta=4 nullable=0 is_null=0 */
###   @8=337 /* INT meta=0 nullable=0 is_null=0 */
###   @9='jpeg' /* VARSTRING(10) meta=10 nullable=0 is_null=0 */
###   @10=600 /* INT meta=0 nullable=0 is_null=0 */
###   @11=1349714716 /* TIMESTAMP meta=0 nullable=0 is_null=0 */
###   @12=1349714716 /* TIMESTAMP meta=0 nullable=0 is_null=0 */
###   @13=0 /* INT meta=0 nullable=0 is_null=0 */
###   @14='1c1fa57bad8f2fd2eb529fe5e4aa9f35' /* VARSTRING(32) meta=32 nullable=0 is_null=0 */
### SET
###   @1=51745159 /* INT meta=0 nullable=0 is_null=0 */
###   @2=897405024 /* INT meta=0 nullable=0 is_null=0 */
###   @3=201 /* INT meta=0 nullable=0 is_null=0 */
###   @4=47 /* INT meta=0 nullable=0 is_null=0 */
###   @5=0 /* INT meta=0 nullable=0 is_null=0 */
###   @6=180 /* INT meta=0 nullable=0 is_null=0 */
###   @7=0.362018             /* FLOAT meta=4 nullable=0 is_null=0 */
###   @8=337 /* INT meta=0 nullable=0 is_null=0 */
###   @9='jpeg' /* VARSTRING(10) meta=10 nullable=0 is_null=0 */
###   @10=600 /* INT meta=0 nullable=0 is_null=0 */
###   @11=1349714716 /* TIMESTAMP meta=0 nullable=0 is_null=0 */
###   @12=1349736357 /* TIMESTAMP meta=0 nullable=0 is_null=0 */
###   @13=1 /* INT meta=0 nullable=0 is_null=0 */
###   @14='1c1fa57bad8f2fd2eb529fe5e4aa9f35' /* VARSTRING(32) meta=32 nullable=0 is_null=0 */
# at 747388250

这时查看master和2个slave上这个数据的情况

mysql> select * from s_user_logo_7 where uid=51745159 and pid=897405024;
+------+----------+-----------+------+-----+-------+------+----------+-------+--------+--------+---------------------+---------------------+------------+----------------------------------+
|HOST  | uid      | pid       | logo | top | lleft | size | zoom     | width | format | height | ctime               | mtime               | commentnum | md5                              |
+------+----------+-----------+------+-----+-------+------+----------+-------+--------+--------+---------------------+---------------------+------------+----------------------------------+
|MASTER| 51745159 | 897405024 |  201 |  47 |     0 |  180 | 0.362018 |   337 | jpeg   |    600 | 2012-10-09 00:45:16 | 2012-10-09 06:45:57 |          1 | 1c1fa57bad8f2fd2eb529fe5e4aa9f35 |
+------+----------+-----------+------+-----+-------+------+----------+-------+--------+--------+---------------------+---------------------+------------+----------------------------------+
|SLAVE1| 51745159 | 897405024 |  201 |  47 |     0 |  180 | 0.362018 |   337 | jpeg   |    600 | 2012-10-09 00:45:16 | 2012-10-09 06:45:57 |          1 | 1c1fa57bad8f2fd2eb529fe5e4aa9f35 |
+------+----------+-----------+------+-----+-------+------+----------+-------+--------+--------+---------------------+---------------------+------------+----------------------------------+
|SLAVE2| 51745159 | 897405024 |  201 |  47 |     0 |  180 | 0.362018 |   337 | jpeg   |    600 | 2012-10-09 00:45:16 | 2012-10-09 00:45:16 |          0 | 1c1fa57bad8f2fd2eb529fe5e4aa9f35 |
+------+----------+-----------+------+-----+-------+------+----------+-------+--------+--------+---------------------+---------------------+------------+----------------------------------+

从数据上看不出为什么replication停掉，应该update可以正常执行啊
查过slave2 的relay log中的binlog，和master上一模一样，百思不得其解
binlog_format设置的是mixed

开始怀疑是timestamp时区问题，查看了master，和两个slave上的时区设置，都是一样的

出问题的表的表结构如下
*************************** 1. row ***************************
       Table: s_user_logo_7
Create Table: CREATE TABLE `s_user_logo_7` (
  `uid` int(11) NOT NULL DEFAULT '0' COMMENT 'SPLIT_KEY',
  `pid` int(11) NOT NULL DEFAULT '0',
  `logo` int(11) NOT NULL DEFAULT '0',
  `top` int(11) NOT NULL DEFAULT '0',
  `lleft` int(11) NOT NULL DEFAULT '0',
  `size` int(11) NOT NULL DEFAULT '0',
  `zoom` float NOT NULL DEFAULT '0',
  `width` int(11) NOT NULL DEFAULT '0',
  `format` varchar(10) NOT NULL DEFAULT '',
  `height` int(11) NOT NULL DEFAULT '0',
  `ctime` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
  `mtime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `commentnum` int(11) NOT NULL DEFAULT '0',
  `md5` varchar(32) NOT NULL DEFAULT '',
  KEY `uid` (`uid`,`ctime`),
  KEY `pid` (`pid`),
  KEY `md5` (`md5`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1

chinafenghao

@ayalastrike
楼主，我有两个疑问
1、在master上查看出问题的binlog /usr/local/mysql/bin/mysqlbinlog mysql-bin.000087 -vv --start-position=747387897 | less
你看了slave2上的relay log里面是啥内容吗？

2、mixed格式的日志，这个更新sql应该是statement-based的，不会是row的。sql中有啥不确定函数?

ayalastrike

查看了slave2上的relay log，和master上binlog内容是完全一样的

ayalastrike

在slave上unix timestamp转换也没有问题

mysql> select FROM_UNIXTIME(1349714716);         
+---------------------------+
| FROM_UNIXTIME(1349714716) |
+---------------------------+
| 2012-10-09 00:45:16       |
+---------------------------+
1 row in set (0.00 sec)

mysql> select UNIX_TIMESTAMP("2012-10-09 00:45:16");            
+---------------------------------------+
| UNIX_TIMESTAMP("2012-10-09 00:45:16") |
+---------------------------------------+
|                            1349714716 |
+---------------------------------------+
1 row in set (0.00 sec)

chinafenghao

@ayalastrike
sorry，关于slave2的replay-log我没看仔细。你1楼描述了。你能恢复这条sql，手工在slave2执行一次呢？

ayalastrike

/usr/local/mysql/bin/mysqlbinlog relay-bin.000002 -vv --start-position=267860420 --stop-position=267860800| mysql -S /var/lib/mysql/mysql.sock -u root -p kx_info      

ERROR 1032 (HY000) at line 34: Can't find record in 's_user_logo_7'

在slave 2手动执行relay log同样不行
推测是where语句哪里解析不对，导致找不到记录，无法update

cenalulu

对比下slave1和slave2的表结构，column类型不对也会造成error

ayalastrike

表结构对比了，master， slave 1， slave 2上是一致的

yl_it

学习，学习了。

lingboy

楼主的问题解决了吗？我遇到了和你一样的问题，从库的数据手动查了没发现什么问题，也是同步时更新出错。