--log-slave-updates is OFF but some updates are still logged to the slave binary log?

Posted by quanta on Server Fault See other posts from Server Fault or by quanta
Published on 2012-04-04T12:10:35Z Indexed on 2012/04/05 5:32 UTC
Read the original article Hit count: 810

MySQL version 5.5.14

According to the document, by the default, slave does not log to its binary log any updates that are received from a master server.

Here are my config. on the slave:

# egrep 'bin|slave' /etc/my.cnf
relay-log=mysqld-relay-bin
log-bin = /var/log/mysql/mysql-bin
binlog-format=MIXED
sync_binlog = 1
log-bin-trust-function-creators = 1

mysql> show global variables like 'log_slave%';
+-------------------+-------+
| Variable_name     | Value |
+-------------------+-------+
| log_slave_updates | OFF   |
+-------------------+-------+
1 row in set (0.01 sec)

mysql> select @@log_slave_updates;
+---------------------+
| @@log_slave_updates |
+---------------------+
|                   0 |
+---------------------+
1 row in set (0.00 sec)

but slave still logs the some changes to its binary logs, let's see the file size:

-rw-rw---- 1 mysql mysql  37M Apr  1 01:00 /var/log/mysql/mysql-bin.001256
-rw-rw---- 1 mysql mysql  25M Apr  2 01:00 /var/log/mysql/mysql-bin.001257
-rw-rw---- 1 mysql mysql  46M Apr  3 01:00 /var/log/mysql/mysql-bin.001258
-rw-rw---- 1 mysql mysql 115M Apr  4 01:00 /var/log/mysql/mysql-bin.001259
-rw-rw---- 1 mysql mysql 105M Apr  4 18:54 /var/log/mysql/mysql-bin.001260

and the sample query when reading these binary files with mysqlbinlog utility:

#120404 19:08:57 server id 3  end_log_pos 110324763     Query   thread_id=382435        exec_time=0     error_code=0
SET TIMESTAMP=1333541337/*!*/;
INSERT INTO norep_SplitValues VALUES ( NAME_CONST('cur_string',_utf8'118212' COLLATE 'utf8_general_ci'))
/*!*/;
# at 110324763

Did I miss something?


Reply to @RolandoMySQLDBA:

If replication brought this over, then the same query has to be in the relay logs. Please go find the relay log that has the INSERT query with the same TIMESTAMP (1333541337).

There is no such query with the same TIMESTAMP in the relay logs.

If you cannot find it in the relay logs, then look and see if Infobright is posting the INSERT query. In that instance, the INSERT should be recorded in the binary logs of the Slave.

Looking more deeply into the binary logs, I see that almost of the queries are CREATE/INSERT/UPDATE/DROP "temporary" tables, something like this:

# at 123873315
#120405  0:42:04 server id 3  end_log_pos 123873618     Query   thread_id=395373        exec_time=0     error_code=0
SET TIMESTAMP=1333561324/*!*/;
SET @@session.pseudo_thread_id=395373/*!*/;
CREATE TEMPORARY TABLE `norep_tmpcampaign` (
    `campaignid` INTEGER(11)  NOT NULL DEFAULT '0' ,
    `status` INTEGER(11)  NOT NULL DEFAULT '0' ,
    `updated` DATETIME,
         KEY `campaignid` (`campaignid`)             
        )ENGINE=MEMORY
/*!*/;
# at 123873618
#120405  0:42:04 server id 3  end_log_pos 123873755     Query   thread_id=395373        exec_time=0     error_code=0
SET TIMESTAMP=1333561324/*!*/;
DROP TABLE IF EXISTS `norep_tmpcampaign1` /* generated by server */

"temporary" here means that they are dropped after calculation is done. I also tells the slave not to replicate any statement matches the norep_ wildcard pattern:

replicate-wild-ignore-table=%.norep_%

But there is an exception table in the binary logs:

# at 123828094
#120405  0:37:21 server id 3  end_log_pos 123828495     Query   thread_id=395209        exec_time=0     error_code=0
SET TIMESTAMP=1333561041/*!*/;
INSERT INTO sessions  (SessionId, ApplicationName, Created, Expires,   LockDate, LockId, Timeout, Locked, SessionItems, Fla
gs)  Values('pgv2exo4y4vo4ccz44vwznu0', '/', '2012-04-05 00:37:21', '2012-04-05 00:57:21',   '2012-04-05 00:37:21', 0, 20, 
0, 'AwAAAP////8IdXNlcm5hbWUGdXNlcmlkCHBlcm1pdGlkAgAAAAQAAAAGAAAAAQABAAEA', 0)
/*!*/;

Description:

mysql> desc reportingdb.sessions;
+-----------------+------------------+------+-----+---------------------+-------+
| Field           | Type             | Null | Key | Default             | Extra |
+-----------------+------------------+------+-----+---------------------+-------+
| SessionId       | varchar(64)      | NO   | PRI |                     |       |
| ApplicationName | varchar(255)     | NO   |     |                     |       |
| Created         | timestamp        | NO   |     | 0000-00-00 00:00:00 |       |
| Expires         | timestamp        | NO   |     | 0000-00-00 00:00:00 |       |
| LockDate        | timestamp        | NO   |     | 0000-00-00 00:00:00 |       |
| LockId          | int(11) unsigned | NO   |     | NULL                |       |
| Timeout         | int(11) unsigned | NO   |     | NULL                |       |
| Locked          | bit(1)           | NO   |     | NULL                |       |
| SessionItems    | varchar(255)     | YES  |     | NULL                |       |
| Flags           | int(11)          | NO   |     | NULL                |       |
+-----------------+------------------+------+-----+---------------------+-------+

I'm sure all these queries are posting by MySQL, not Infobright:

$ mysql-ib -u root -p
Enter password: 
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 48971
Server version: 5.1.40 build number (revision)=IB_4.0.5_r15240_15370(ice) (static)

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select * from information_schema.tables where table_name='sessions';
Empty set (0.02 sec)

I've been trying some INSERT/UPDATE queries with testing tables on the master, it is copied to the relay logs, not binary logs on slave:

# at 311664029
#120405  0:15:23 server id 1  end_log_pos 311664006     Query   thread_id=10458250      exec_time=0     error_code=0
use testuser/*!*/;
SET TIMESTAMP=1333559723/*!*/;
update users set email2='[email protected]' where id=22
/*!*/;

Pay attention to the server id, in the relay logs, server id is master's (1) and in the binary log, server id is slave's (3 in this case).


Reply to @RolandoMySQLDBA: Thu Apr 5 10:06:00 ICT 2012

Run CREATE DATABASE quantatest; on the Master now, please. Tell me if CREATE DATABASE quantatest; showed up in the Slave's Binary Logs.

As I said above:

I've been trying some INSERT/UPDATE queries with testing tables on the master, it is copied to the relay logs, not binary logs

and you can guess, IO thread copied it to the relay logs, not binary logs.

#120405 10:07:25 server id 1  end_log_pos 347573819     Query   thread_id=10480775      exec_time=0     error_code=0
SET TIMESTAMP=1333595245/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
create database quantatest
/*!*/;

The question must probably change to: why some update queries still logged to the slave binary logs althrough --log-slave-updates is disabled? Where they come from?

Here are few last:

/*!*/;
# at 27492197
#120405 10:12:45 server id 3  end_log_pos 27492370      Query   thread_id=410353        exec_time=0     error_code=0
SET TIMESTAMP=1333595565/*!*/;
CREATE TEMPORARY TABLE norep_SplitValues (
        value VARCHAR(1000) NOT NULL
      ) ENGINE=MEMORY
/*!*/;
# at 27492370
#120405 10:12:45 server id 3  end_log_pos 27492445      Query   thread_id=410353        exec_time=0     error_code=0
SET TIMESTAMP=1333595565/*!*/;
BEGIN
/*!*/;
# at 27492445
#120405 10:12:45 server id 3  end_log_pos 27492619      Query   thread_id=410353        exec_time=0     error_code=0
SET TIMESTAMP=1333595565/*!*/;
INSERT INTO norep_SplitValues VALUES ( NAME_CONST('cur_string',_utf8'119577' COLLATE 'utf8_general_ci'))
/*!*/;
# at 27492619
#120405 10:12:45 server id 3  end_log_pos 27492695      Query   thread_id=410353        exec_time=0     error_code=0
SET TIMESTAMP=1333595565/*!*/;
COMMIT
/*!*/;
# at 27492918
#120405 10:12:46 server id 3  end_log_pos 27493115      Query   thread_id=410353        exec_time=0     error_code=0
SET TIMESTAMP=1333595566/*!*/;
SELECT `reportingdb`.`selfserving_get_locationad`(_utf8'3' COLLATE 'utf8_general_ci',_utf8'' COLLATE 'utf8_general_ci')
/*!*/;
# at 27493199
#120405 10:12:46 server id 3  end_log_pos 27493353      Query   thread_id=410353        exec_time=0     error_code=0
SET TIMESTAMP=1333595566/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
DROP TEMPORARY TABLE IF EXISTS `norep_SplitValues` /* generated by server */
/*!*/;

© Server Fault or respective owner

Related posts about mysql

Related posts about replication