MySQL Bugs: #65837: Mixed has issues in shell prompt DML operations

Bug #65837	Mixed has issues in shell prompt DML operations
Submitted:	6 Jul 2012 14:53	Modified:	12 Aug 2012 15:05
Reporter:	Mannoj S	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S1 (Critical)
Version:	5.5.25	OS:	Linux (CentOS release 5.8 (Final))
Assigned to:		CPU Architecture:	Any
Tags:	MIXED Binary Logging

Description:
SBL - Has issue in picking non-deterministic values.
RBL - Has issue in picking huge updates or bulk updates. Even turing off query_cache.
MIXED - Works fine for non-deterministic values and bulk updates but it NEVER logged the binlog when you run in shell prompt. Like below manner.
-------------------------
mysql -uroot -p*** << EOF
use db_1;
source /root/insert.txt ;
EOF
-------------------------

But when I login to mysql > prompt. And exeucte source /root/insert.txt ; It gets logged into binlog for mixed. Something am I missing? But I feel its biggest flaw when the database takes the records from shell and reflects in existing db whereas binlog stays not bothered !!!

How to repeat:
SBL - Has issue in picking non-deterministic values.
RBL - Has issue in picking huge updates or bulk updates. Even turing off query_cache.
MIXED - Works fine for non-deterministic values and bulk updates but it NEVER logged the binlog when you run in shell prompt. Like below manner.
-------------------------
mysql -uroot -p*** << EOF
use db_1;
source /root/insert.txt ;
EOF
-------------------------

But when I login to mysql > prompt. And exeucte source /root/insert.txt ; It gets logged into binlog for mixed. Something am I missing? But I feel its biggest flaw when the database takes the records from shell and reflects in existing db whereas binlog stays not bothered !!!

Suggested fix:
Let the shell prompt logging to get logged for mixed.

Please, send some simple insert.txt file's content that demonstrates the problem and your my.cnf file content.

Triaged even more and found that if insert is given as db_name.table_name it doesn't log in to binlog for Stamenent and Mixed. But ROW picks it up. When it is given in below manner, it does log for STATEMENT, MIXED and ROW too. 
use pleaselog; 
insert into pleaselog.hitme (dates, class, status, money) values (current_timestamp(), 'FIRST CLASS, SECOND', 'ALIVE', 1232);

let me know if you still require my.cnf

If you can find explanation of this (based on my.cnf settings like binlog-do-*) at http://dev.mysql.com/doc/refman/5.5/en/replication-options-binary-log.html, I'd just say this is not a bug. 

If you need more explanations from somebody else, please, upload your my.cnf file content.

Right so here is my  my.cnf for "5.5.25"
As an fyi.. SBL and mixed works fine for this kinda scenario in 5.1.61 

my.cnf for "5.5.25"

[client]
port                                = 3306
socket                              = /var/lib/mysql/mysql.sock

[mysqld]
port                                = 3306
datadir                             = /var/lib/mysql
socket                              = /var/lib/mysql/mysql.sock
user                                = mysql
old_passwords                       = 1
max_connections                     = 4096
max_connect_errors                  = 256
max_allowed_packet                  = 1024M
binlog_cache_size                   = 16M
max_binlog_size = 268435456
max_heap_table_size                 = 1024M
read_buffer_size                    = 32M
read_rnd_buffer_size                = 1024M
sort_buffer_size                    = 1024M
join_buffer_size                    = 1024M
thread_cache_size                   = 8
thread_concurrency                  = 32
query_cache_size                    = 0
query_cache_type = OFF
query_cache_limit                   = 0
#ft_min_word_len                     = 4
#memlock
default-storage-engine              = innodb
thread_stack                        = 256K
transaction_isolation               = REPEATABLE-READ
tmp_table_size                      = 1024M
log-bin                             = mysql-buds
binlog-format			    = MIXED
binlog-ignore-db		    = mysql

long_query_time                     = 320
server-id                           = 1
innodb_additional_mem_pool_size     = 64M
innodb_buffer_pool_size             = 12G
innodb_thread_concurrency           = 64
innodb_flush_log_at_trx_commit      = 2
innodb_log_buffer_size              = 8M
innodb_log_file_size                = 2047M
innodb_log_files_in_group           = 2
innodb_max_dirty_pages_pct          = 90
innodb_lock_wait_timeout            = 320
innodb_file_per_table

[mysqldump]
quick
max_allowed_packet                  = 64M

[mysql]
#no-auto-rehash

[myisamchk]
key_buffer_size                     = 512M
sort_buffer_size                    = 512M
read_buffer                         = 8M
write_buffer                        = 8M

[mysqlhotcopy]
interactive-timeout

[mysqld_safe]
open-files-limit                    = 8192
log-error                           = /var/log/mysqld.log
pid-file                            = /var/run/mysqld/mysqld.pid

OK, so you have explcit binlog-ignore-db=mysql in my.cnf. Please, check this manual page, http://dev.mysql.com/doc/refman/5.5/en/replication-rules-db-options.html, explains the results you get.

If it does NOT, again, please, upload simple inserts.txt file that demonstrates the problem. Namely, I wonder if you have "use any_db" in it when you get the problem.

No kidding. The article has nothing to do with my problem.

Let me explain the issue again more elaborately.
I have mysql 5.5.25 I enabled mixed logging and kept mysql in nolog mode for replication, rest of the databases will be recorded in binlogs. 
When I create a table on a newly created database and insert records mentioning use db_name; and then seed inserts.. it logs the data in binlog. When I just login to mysql prompt and issue inserts prefixing db_name.table_name it doesn't log in bin log. ex: 
insert into pleaselog.hitme (dates, class, status, money) values (current_timestamp(), 'FIRST CLASS, SECOND', 'ALIVE', 1232);
insert into pleaselog.hitme (dates, class, status, money) values (current_timestamp(), 'FIRST CLASS, SECOND', 'ALIVE', 1232);
insert into pleaselog.hitme (dates, class, status, money) values (current_timestamp(), 'FIRST CLASS, SECOND', 'ALIVE', 1232); 

In this way the inserts are not logged in binary log. When I run the above lines *10000 times in a file say inserts.txt and run them without doing "use db_name;" it gets logged in tables but not in binary logs when I run show binary logs; is says 107 bytes. But when I do run the same file having first line as use db_name; then the bytes increases that shows binary logs are getting added. I tested this in previous stable release 5.1.63 it goes fine for mixed even without explicitly using mentioning "use db_name;" . 

On one hand when inserts and updates and selects are way faster when compared to older versions but when db the records are is missing in an incremental backup in the form of binlogs its a biggest flaw if you ask me. Can you please escalate this ??

Here is the table description..

CREATE TABLE `hitme` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `dates` datetime DEFAULT NULL,
  `class` varchar(20) DEFAULT NULL,
  `status` varchar(20) DEFAULT NULL,
  `money` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=innodb AUTO_INCREMENT=88243 DEFAULT CHARSET=latin1 ;

Manual page I mentioned clearly says:

"For binary logging, the steps involved are listed here:

    Are there any --binlog-do-db or --binlog-ignore-db options?

        Yes.  Continue to step 2.

        No.  Log the statement and exit.

    Is there a default database (has any database been selected by USE)?

        Yes.  Continue to step 3.

        No.  Ignore the statement and exit."

So, you have binlog-ignore-db option in my.cnf, thus we go to step 2. Then, there is no default database, so statement is ignored. Exactly as documented. Manual page for 5.1 says exactly the same.

Let me make a test according to your description, on 5.1.x:

macbook-pro:5.1 openxs$ bin/mysqld_safe --log-bin --binlog-format=mixed --binlog-ignore-db=mysql &
[1] 55588
macbook-pro:5.1 openxs$ 120707 21:34:28 mysqld_safe Logging to '/Users/openxs/dbs/5.1/var/macbook-pro.err'.
chown: /Users/openxs/dbs/5.1/var/macbook-pro.err: Operation not permitted
120707 21:34:29 mysqld_safe Starting mysqld daemon with databases from /Users/openxs/dbs/5.1/var

macbook-pro:5.1 openxs$ bin/mysql -uroot
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.1.64-debug-log Source distribution

Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

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

mysql> show variables like 'binlog%';
+-----------------------------------------+-------+
| Variable_name                           | Value |
+-----------------------------------------+-------+
| binlog_cache_size                       | 32768 |
| binlog_direct_non_transactional_updates | OFF   |
| binlog_format                           | MIXED |
+-----------------------------------------+-------+
3 rows in set (0.01 sec)

mysql> create table test.t(c1 int);
Query OK, 0 rows affected (0.12 sec)

mysql> insert into test.t values(1);
Query OK, 1 row affected (0.07 sec)

mysql> use test;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> insert into test.t values(2);
Query OK, 1 row affected (0.04 sec)

mysql> show master status;
+------------------------+----------+--------------+------------------+
| File                   | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------------------+----------+--------------+------------------+
| macbook-pro-bin.000001 |      197 |              | mysql            |
+------------------------+----------+--------------+------------------+
1 row in set (0.00 sec)

mysql> show binlog events in 'macbook-pro-bin.000001';
+------------------------+-----+-------------+-----------+-------------+---------------------------------------------+
| Log_name               | Pos | Event_type  | Server_id | End_log_pos | Info                                        |
+------------------------+-----+-------------+-----------+-------------+---------------------------------------------+
| macbook-pro-bin.000001 |   4 | Format_desc |         1 |         106 | Server ver: 5.1.64-debug-log, Binlog ver: 4 |
| macbook-pro-bin.000001 | 106 | Query       |         1 |         197 | use `test`; insert into test.t values(2)    |
+------------------------+-----+-------------+-----------+-------------+---------------------------------------------+
2 rows in set (0.04 sec)

So, as soon as there is no default database, statements are NOT logged (as manual says). When I set default database explicitly (and it is not mysql database, that is ignored), we got statement logged. All these in MIXED mode.

If I understood you correctly, you claimed that on 5.1.63 all statements were logged in this case, unlike on 5.5.25.

I'd happily escalate a bug, but I see no bug here. So, please, either send a complete, repeatable test case (that is different from mine above and proves that manual is wrong), or just do it by the manual... Both on 5.1 and on 5.5.

If a gap is documented and you call it as "not a bug". I may have to agree to you according to your process. But if I have a tab in mysql website like what we have as devZone, librarian, articles, forums, bugs, etc.. likewise if I have a tab called "Fundamental glitches", my post would be in there firstly. 

Lets be more practical than what we see in docs ... I may not be that much worried if a database is throwing performance related issues or slow reads or writes. When I rely on a database server that gives me backup in any form that the prod database has been updated and at any cost I should be be able to get them back without any data mismatches. 

Also another note along with this bug,.. sorry.. a fundamental glitch. If I have a database Binlog_Do_DB = tested. And try to insert on another db_name.table. Please see below.

mysql> show master status;
+-------------------------+----------+--------------+------------------+
| File                    | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+-------------------------+----------+--------------+------------------+
| mysql1_masterbin.000003 |      106 | tested       |                  | 
+-------------------------+----------+--------------+------------------+

mysql> use tested;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> insert into pleaselog.hitme (dates, class, status, money) values (current_timestamp(), 'FIRST CLASS, SECOND', 'ALIVE', 1232);
Query OK, 1 row affected (0.03 sec)

mysql> insert into pleaselog.hitme (dates, class, status, money) values (current_timestamp(), 'FIRST CLASS, SECOND', 'ALIVE', 1232);
Query OK, 1 row affected (0.00 sec)

mysql> insert into pleaselog.hitme (dates, class, status, money) values (current_timestamp(), 'FIRST CLASS, SECOND', 'ALIVE', 1232);
Query OK, 1 row affected (0.00 sec)

mysql> flush logs;
Query OK, 0 rows affected (0.00 sec)

Does this insert get logged into binary log? According to me it shouldn't but according to mysql it does. While importing tested database or DR server I get this exception along with it.

[root@db2 snapshot]# mysql -uroot -proot123 --socket=/tmp/mysql1dr.sock  << EOF
> source mysql1_masterbin.000001.sql; source mysql1_masterbin.000002.sql; source mysql1_masterbin.000003.sql; source mysql1_masterbin.000004.sql ;
> EOF
ERROR 1146 (42S02) at line 23 in file: 'mysql1_masterbin.000003.sql': Table 'pleaselog.hitme' doesn't exist
[root@db2 snapshot]#

You might have this one too documented somewhere.  But as a DBA when the DR is required to rebuild he/she faces super pressure where the IT heads and management look at us to get this rebuilt done ASAP. And these errors makes us a long procedure to triage and fix thus we change ASAP to ALAP.

These can be looked and cemented by your developers and testers not sure how many of others using mysql are aware of this glitch and running a batch process without using "use db_name ;" or am I the only person late reacting to this.

Suggested fix: Don't accept DML operations that are issued as db_name.table_name. Just throw an error telling "don't prefix db_name for DML operations- please select the database first using use db_name;". This is not a fix but a workaround to safeguard our redundancy. 

Hence please escalate if you are ready to accept critics to mysql to make it even more better. 

Thank you!!

IMHO current behavior is clearly documented, so can be considered a feature, even if this feature leads to problems in your case.

Maybe you just want it to work the way you expected, independently of default database setting? Then it will be a duplicate of a known and accepted FR, Bug #61767.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".