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

Question

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 */
/*!*/;

Solution 1

The server-id values show things are working as expected, to me.

Each statement is associated with the server-id from the server on which that statement originated (this is how a mysql server knows not to replicate statements from itself, unless you use a particular setting). This association is preserved even through replication.

You can see that statements from the master (server-id 1) are only replicated, stored in relay logs, then executed on the slave without writing to the slave binlogs. The statements you see associated with server-id 3 (the slave) must be getting executed locally on the slave db. This is why they get written to the binlogs. log-slave-updates will not exclude locally written queries.

You should look at the traffic on your slave db: something must be connecting and executing those queries. If you don't see anything in the processlist (no persistent connections), you could try turning on the general log or capturing mysql traffic using tcpdump or something.

Also: you say you want the binlogs on the slave for incremental backups. If you are intentionally excluding replication traffic from your slave binlogs, that doesn't sound like you actually have the ability to use those binlogs for point in time backups/recovery. You will be missing all of the replication traffic. So maybe you should be using log-slave-updates after all? Not sure.

-Dan

Solution 2

In your question, you said the binary logs on the Slave has

#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

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).

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.

UPDATE 2012-04-04 14:49 EDT

Here is an experiment. Run the following query on the Master:

CREATE DATABASE quantatest;

This statement must land in the relay logs on the Slave after execution on the Master. Under normal circumstances, this statement should not appear in the Slave's binary logs having log-slave-updates disabled.

According to your question, with you have log-slave-updates disabled, you say this query will appear in the Slave's binary logs.

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

Comments

[gokva]

try stopping mysqld, and then doing ps -ef | mysql to check for any wayward mysql processes that might be running unchecked....

[Greg Petersen]

I also run Infobright on this slave but I'm sure it doesn't related to the MySQL. There is only one MySQL instance on this server. Do you have any other ideas?

[chocripple]

remove "log-bin = /var/log/mysql/mysql-bin" from my.cnf ?

[Greg Petersen]

I need these binary logs for the incremental backup purpose. The question is: why it can happen with log_slave_updates=OFF?

[Greg Petersen]

Yes, I'm using standard MySQL Replication. ICE doesn't support replication and I've not hear about Tungsten.

[Greg Petersen]

You are right. Those are called from functions/procedures which are executed locally on the slave. log-slave-updates must be enabled for incremental backups based on the binlogs on the slave.