Bug #40360 Binlog related errors with binlog off
Submitted: 27 Oct 2008 21:27 Modified: 10 Nov 2008 20:12
Reporter: David Stavisski
Status: Closed
Category:Server: InnoDB Severity:S2 (Serious)
Version:5.1.29 OS:Microsoft Windows
Assigned to: Mats Kindahl Target Version:5.1.30
Triage: Triaged: D2 (Serious) / R3 (Medium) / E3 (Medium)

[27 Oct 2008 21:27] David Stavisski
Description:
after upgrading to 5.1.28 from 5.1.28 getting an error message on every update:

Binary logging not possible. Message: Transaction level 'READ-COMMITTED' in InnoDB is not
safe for binlog mode 'STATEMENT'

The binlog and replication is off.

How to repeat:
set transaction isolation to Read Commited
update a table row
[27 Oct 2008 21:29] David Stavisski
intended: upgraded 5.1.28 -> 5.1.29
[28 Oct 2008 5:22] Valeriy Kravchuk
Thank you for a problem report. Please, send your my.cnf. I can not repeat the behaviour
described:

C:\Program Files\MySQL\MySQL Server 5.0\bin>mysql -uroot -proot -P3310 test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 20
Server version: 5.1.29-rc-community MySQL Community Server (GPL)

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> set global transaction isolation level read committed;
Query OK, 0 rows affected (0.05 sec)

mysql> show variables like '%bin%';
+---------------------------------+------------+
| Variable_name                   | Value      |
+---------------------------------+------------+
| binlog_cache_size               | 32768      |
| binlog_format                   | STATEMENT  |
| innodb_locks_unsafe_for_binlog  | OFF        |
| log_bin                         | OFF        |
| log_bin_trust_function_creators | OFF        |
| log_bin_trust_routine_creators  | OFF        |
| max_binlog_cache_size           | 4294967295 |
| max_binlog_size                 | 1073741824 |
| sql_log_bin                     | ON         |
| sync_binlog                     | 0          |
+---------------------------------+------------+
10 rows in set (0.06 sec)

mysql> create table tlb(c1 int primary key, c2 int) engine=InnoDB;
Query OK, 0 rows affected (0.36 sec)

mysql> insert into tlb values(1,1);
Query OK, 1 row affected (0.11 sec)

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

mysql> update tlb set c2=2;
Query OK, 1 row affected (0.11 sec)
Rows matched: 1  Changed: 1  Warnings: 0

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

What I am doing wrong?
[28 Oct 2008 16:34] Valeriy Kravchuk
Sorry, my fault (I had forgotten that SET GLOBAL will work for new sessions). Verified
like this:

C:\Program Files\MySQL\MySQL Server 5.0\bin>mysql -uroot -proot -P3310 test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 21
Server version: 5.1.29-rc-community MySQL Community Server (GPL)

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> CREATE TABLE `datetest` (
    ->   `a` bigint(20) unsigned NOT NULL,
    ->   `b` datetime default NULL
    -> ) ENGINE=InnoDB;
Query OK, 0 rows affected (0.11 sec)

mysql> INSERT INTO test.datetest VALUES(1,'4269-02-29');
ERROR 1598 (HY000): Binary logging not possible. Message: Transaction level 'REA
D-COMMITTED' in InnoDB is not safe for binlog mode 'STATEMENT'
mysql> show variables like '%bin%';
+---------------------------------+------------+
| Variable_name                   | Value      |
+---------------------------------+------------+
| binlog_cache_size               | 32768      |
| binlog_format                   | STATEMENT  |
| innodb_locks_unsafe_for_binlog  | OFF        |
| log_bin                         | OFF        |
| log_bin_trust_function_creators | OFF        |
| log_bin_trust_routine_creators  | OFF        |
| max_binlog_cache_size           | 4294967295 |
| max_binlog_size                 | 1073741824 |
| sql_log_bin                     | ON         |
| sync_binlog                     | 0          |
+---------------------------------+------------+
10 rows in set (0.02 sec)
[29 Oct 2008 4:15] Tom Daly
I have just downloaded and installed 5.1.29 on RHEL 5 and I am seeing the same problem.

to reproduce : 
mysql < test.sql 
ERROR 1598 (HY000) at line 11: Binary logging not possible. Message: Transaction level
'READ-COMMITTED' in InnoDB is not safe for binlog mode 'STATEMENT'

cat test.sql 
DROP TABLE IF EXISTS customer;
CREATE TABLE customer
  (id           integer not null,
   itemid       char(20),
   quantity     integer,             
   customerid   integer,
   value                numeric(12,2),
   PRIMARY KEY C_custinvkey (id)
) ENGINE = InnoDB;

CREATE INDEX test_idx ON customer(customerid);

mysql> show variables like '%bin%';
+---------------------------------+----------------------+
| Variable_name                   | Value                |
+---------------------------------+----------------------+
| binlog_cache_size               | 32768                | 
| binlog_format                   | STATEMENT            | 
| innodb_locks_unsafe_for_binlog  | OFF                  | 
| log_bin                         | OFF                  | 
| log_bin_trust_function_creators | OFF                  | 
| log_bin_trust_routine_creators  | OFF                  | 
| max_binlog_cache_size           | 18446744073709551615 | 
| max_binlog_size                 | 1073741824           | 
| sql_log_bin                     | ON                   | 
| sync_binlog                     | 0                    | 
+---------------------------------+----------------------+
10 rows in set (0.00 sec)

mysql> show variables like '%innodb%';
+---------------------------------+---------------------------+
| Variable_name                   | Value                     |
+---------------------------------+---------------------------+
| have_innodb                     | YES                       | 
| innodb_adaptive_hash_index      | ON                        | 
| innodb_additional_mem_pool_size | 20971520                  | 
| innodb_autoextend_increment     | 8                         | 
| innodb_autoinc_lock_mode        | 1                         | 
| innodb_buffer_pool_size         | 5242880000                | 
| innodb_checksums                | OFF                       | 
| innodb_commit_concurrency       | 0                         | 
| innodb_concurrency_tickets      | 500                       | 
| innodb_data_file_path           | ibdata1:10000M:autoextend | 
| innodb_data_home_dir            | /data/mysql/var           | 
| innodb_doublewrite              | OFF                       | 
| innodb_fast_shutdown            | 1                         | 
| innodb_file_io_threads          | 4                         | 
| innodb_file_per_table           | ON                        | 
| innodb_flush_log_at_trx_commit  | 1                         | 
| innodb_flush_method             | O_DIRECT                  | 
| innodb_force_recovery           | 0                         | 
| innodb_lock_wait_timeout        | 300                       | 
| innodb_locks_unsafe_for_binlog  | OFF                       | 
| innodb_log_buffer_size          | 16777216                  | 
| innodb_log_file_size            | 1677721600                | 
| innodb_log_files_in_group       | 2                         | 
| innodb_log_group_home_dir       | /log/mysql/var/           | 
| innodb_max_dirty_pages_pct      | 15                        | 
| innodb_max_purge_lag            | 0                         | 
| innodb_mirrored_log_groups      | 1                         | 
| innodb_open_files               | 300                       | 
| innodb_rollback_on_timeout      | OFF                       | 
| innodb_support_xa               | OFF                       | 
| innodb_sync_spin_loops          | 20                        | 
| innodb_table_locks              | ON                        | 
| innodb_thread_concurrency       | 0                         | 
| innodb_thread_sleep_delay       | 10000                     | 
+---------------------------

regards
Tom Daly (Sun Microsystems)
[29 Oct 2008 15:25] Trudy Pelzer
Per Joro:
This is a consequence of us changing the default binlog format for 5.1 to statement
(http://bugs.mysql.com/bug.php?id=39812).
It seems that the InnoDB code has an incomplete check in ha_innobase::external_lock() :

6529         /* Statement based binlogging does not work in isolation level
6530         READ UNCOMMITTED and READ COMMITTED since the necessary
6531         locks cannot be taken. In this case, we print an
6532         informative error message and return with an error. */
6533         if (lock_type == F_WRLCK)
6534         {
6535                 ulong const binlog_format= thd_binlog_format(thd);
6536                 ulong const tx_isolation = thd_tx_isolation(current_thd);
6537                 if (tx_isolation <= ISO_READ_COMMITTED &&
6538                     binlog_format == BINLOG_FORMAT_STMT)
6539                 {
6540                         char buf[256];
6541                         my_snprintf(buf, sizeof(buf),
6542                                     "Transaction level '%s' in"
6543                                     " InnoDB is not safe for binlog mode '%s'",
6544                                     tx_isolation_names[tx_isolation],
6545                                     binlog_format_names[binlog_format]);
6546                         my_error(ER_BINLOG_LOGGING_IMPOSSIBLE, MYF(0), buf);
6547                         DBUG_RETURN(HA_ERR_LOGGING_IMPOSSIBLE);
6548                 } 

Note that it doesn't check if binary log is on or off when performing this check.

Workaround: switch to MIXED mode for your installation (as should be the default for new
installations using the config file generated by the installer).
[29 Oct 2008 16:26] David Stavisski
Unfortunately the workaround does not work (or at least not completely):
if you set:
binlog_format=mixed
without enabling the bin-log, the serve does not start complaining that the bon-log is
off. You have to enable it:
log-bin=mysql-bin
which carries a performance penalty.

Thx,
David Stavisski
[29 Oct 2008 16:39] Michael Izioumtchenko
Assigning to Vasil. R/E values based on the assumed one line fix. 
It would be also nice to add a test case for this.
[29 Oct 2008 18:34] Mike Mulligan
I receive this same error when trying to use MySQL 5.1.29 as a respository for Sun
Identity Manager 7.1.1 using Netbeans 6.1.

When I set the repository in Netbeans and select MySQL JDBC driver, I get:

java.sql.SQLException: Binary logging not possible. Message: Transaction level
'READ-COMMITTED' in InnoDB is not safe for binlog mode 'STATEMENT'

I had to roll back to MySQL 5.0.67 to get Sun IdM/Netbeans to work.
[29 Oct 2008 22:08] Vasil Dimov
From sql/log.h:

556 enum enum_binlog_format {
557   /*
558     statement-based except for cases where only row-based can work (UUID()
559     etc):
560   */
561   BINLOG_FORMAT_MIXED= 0,
562   BINLOG_FORMAT_STMT= 1, // statement-based
563   BINLOG_FORMAT_ROW= 2, // row_based
564 /*
565   This value is last, after the end of binlog_format_typelib: it has no
566   corresponding cell in this typelib. We use this value to be able to know if
567   the user has explicitely specified a binlog format at startup or not.
568 */
569   BINLOG_FORMAT_UNSPEC= 3
570 };

So, why is the value returned by thd_binlog_format() BINLOG_FORMAT_STMT when no
--binlog_format has been specified at startup?
[30 Oct 2008 8:01] Vasil Dimov
Sidenote:

This problem is present in 5.1.28 too, and I guess has always been there:

Start mysqld without any binlogging options:

Version: '5.1.28-rc'  socket: '/tmp/mysql.sock'  port: 0  FreeBSD port:
mysql-server-5.1.28_1

mysql> set tx_isolation='read-committed';
Query OK, 0 rows affected (0.00 sec)

mysql> set binlog_format='statement';
Query OK, 0 rows affected (0.00 sec)

mysql> create table t (a int) engine=innodb;
Query OK, 0 rows affected (0.13 sec)

mysql> insert into t values (1);
ERROR 1598 (HY000): Binary logging not possible. Message: Transaction level
'READ-COMMITTED' in InnoDB is not safe for binlog mode 'STATEMENT'

It has just not been discovered because noone bothered to set binlog_format without
turning binlogging on (and also setting tx_isolation to 'read-committed').
[30 Oct 2008 12:34] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/57440

2777 Georgi Kodinov	2008-10-30
      Bug #40360: Binlog related errors with binlog off
      
      Fixed MySQL to return BINLOG_FORMAT_UNSPEC when bin_log is off and no binlog_format
was specified.
[30 Oct 2008 12:37] Georgi Kodinov
Proposed fix to MySQL committed
[30 Oct 2008 12:50] Vasil Dimov
From the commit message:

connect(localhost,root,,test,12000,/home/kgeorge/mysql/bzr/B40360-5.1-5.1.29-rc/mysql-test/var/tmp/master.sock);

are you sure the above is correct?
[30 Oct 2008 14:33] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/57450

2773 Mats Kindahl	2008-10-30
      Bug #40360: Binlog related errors with binlog off
      
      When statement-based replication is used, and the
      transaction isolation level is READ-COMMITTED or stricter,
      InnoDB will print an error because statement-based
      replication might lead to inconsistency between master
      and slave databases. However, when the binary log is not
      engaged, this is not an issue and an error should
      not be printed.
      
      This patch extends the check in InnoDB to also check if
      the binary log is engaged for the thread, that is, open
      and with SQL_LOG_BIN = 1.
[30 Oct 2008 15:00] Mats Kindahl
The submitted patch will is a tentative patch for fixing the issue, awaiting the final
review by Innobase. The patch contain changes to both the server and the InnoDB handler.
[30 Oct 2008 15:15] Vasil Dimov
Just for the records:

The check inside ha_innobase::external_lock() probably originated from the fix of
Bug#23051 READ COMMITTED breaks mixed and statement-based replication.
[3 Nov 2008 12:32] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/57684

2773 Mats Kindahl	2008-11-03
      Bug #40360: Binlog related errors with binlog off
            
      When statement-based replication is used, and the
      transaction isolation level is READ-COMMITTED or stricter,
      InnoDB will print an error because statement-based
      replication might lead to inconsistency between master
      and slave databases. However, when the binary log is not
      engaged, this is not an issue and an error should
      not be printed.
      
      This patch makes thd_binlog_format() return BINLOG_FORMAT_
      UNSPEC when the binary log is not engaged for the given
      thread.
[3 Nov 2008 18:47] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/57711

2774 Mats Kindahl	2008-11-03
      Bug #40360: Binlog related errors with binlog off
      
      Adding missing drop of created table and tidying display.
[4 Nov 2008 10:20] Bugs System
Pushed into 5.1.30  (revid:mats@sun.com-20081103174647-s4jyy5vqe0eo68q0) (version source
revid:mats@sun.com-20081103174647-s4jyy5vqe0eo68q0) (pib:5)
[4 Nov 2008 17:26] Paul DuBois
Noted in 5.1.30 changelog.

With statement-based binary logging format and a transaction 
isolation level of READ COMMITTED or stricter, InnoDB printed an
error because statement-based logging might lead to inconsistency
between master and slave databases. However, this error was printed 
even when binary logging was not enabled (in which case, no such
inconsistency can occur).
[4 Nov 2008 17:26] Paul DuBois
Setting report to NDI pending push into 6.0.x.
[5 Nov 2008 11:28] Miguel Solorzano
Bug: http://bugs.mysql.com/bug.php?id=40513 was marked as duplicate of this one.
[10 Nov 2008 11:50] Bugs System
Pushed into 6.0.8-alpha  (revid:mats@sun.com-20081103174647-s4jyy5vqe0eo68q0) (version
source revid:kgeorge@mysql.com-20081106161825-9biri1v40v7b0kg3) (pib:5)
[10 Nov 2008 20:12] Paul DuBois
Note in 6.0.8 changelog.
[11 Nov 2008 17:33] Paul DuBois
6.0.9 changelog, not 6.0.8.
[21 Nov 2008 22:02] Bugs System
Pushed into 5.1.30-ndb-6.2.17  (revid:mats@sun.com-20081103174647-s4jyy5vqe0eo68q0)
(version source revid:tomas.ulin@sun.com-20081121161314-jhz3twf5xjt8stnh) (pib:5)
[22 Nov 2008 0:45] Bugs System
Pushed into 5.1.30-ndb-6.3.20  (revid:mats@sun.com-20081103174647-s4jyy5vqe0eo68q0)
(version source revid:tomas.ulin@sun.com-20081121210644-zas6e9wa5kuj7d6f) (pib:5)
[27 Nov 2008 15:52] Bugs System
Pushed into 5.1.30-ndb-6.4.0  (revid:mats@sun.com-20081103174647-s4jyy5vqe0eo68q0)
(version source revid:tomas.ulin@sun.com-20081126125835-5sohkzk2jjwpq1wp) (pib:5)
[6 Feb 4:48] James Day
Note that if you use READ-COMMITTED and binary logging (including for replication) 5.1 you
must use row-based binlogging. It's expected that you will see this error if you try to
add rows to an InnoDB table otherwise. For more information see the manual at
http://dev.mysql.com/doc/refman/5.1/en/set-transaction.html . You should change the
transaction isolation level or the binary logging mode.