MySQL Bugs: #39084: Getting intermittent errors with statement-based binary logging

Bug #39084	Getting intermittent errors with statement-based binary logging
Submitted:	28 Aug 2008 4:07	Modified:	10 Nov 2008 14:56
Reporter:	Partha Dutta	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Partitions	Severity:	S1 (Critical)
Version:	5.1.25-rc, 5.1.28, 5.1, 6.0 bzr	OS:	Linux (CentOS 4.4 2.6.9-42.0.3)
Assigned to:	Mattias Jonsson	CPU Architecture:	Any
Tags:	Contribution

Description:
On occasions, we are getting this error both from the application writing to the master, as well as the slave:

Error 'Binary logging not possible. Message: Statement-based format required for this statement, but not allowed by this combination of engines' on query.

This problem is very intermittent, and not at all duplicable, which makes it ever so maddening. It is stress testing our monitoring though :)

This is happening with the innodb storage engine, which is what we use exclusively on these servers, so I don't quite understand the meaning of the error message.

Here is the high level of steps:

1. App creates 9 new tables for staging data to be loaded. All tables are InnoDB and created with option ROW_FORMAT=COMPACT.  Everytime a table is created, it appends an identifier to make a unique name for the table.
2. Data is inserted using INSERT statements to this new table.
3. The base tables are then populated from the staging table with SQL like this:
insert into creative_iobudget_monthly_local(buyer_entity_id,io_id,line_item_id,campaign_id,creative_id,adv_learn_type,is_adjustment,imps,clicks,amt_paid_to_seller,roi_value,ymdh,id) select buyer_entity_id,io_id,line_item_id,campaign_id,creative_id,adv_learn_type,is_adjustment,imps,clicks,amt_paid_to_seller,roi_value,date_format(ymdh, '%Y-%m-01 00:00:00'),id from creative_iobudget_g08081523 where load_attempt=1 order by ymdh,id on duplicate key update creative_iobudget_monthly_local.imps = creative_iobudget_monthly_local.imps + VALUES(imps),creative_iobudget_monthly_local.clicks = creative_iobudget_monthly_local.clicks + VALUES(clicks),creative_iobudget_monthly_local.amt_paid_to_seller = creative_iobudget_monthly_local.amt_paid_to_seller + VALUES(amt_paid_to_seller),creative_iobudget_monthly_local.roi_value =......

There are quite a few of these statements, all with a transaction (the create table is not)
4. After the transaction is committed, the tables are dropped

Here are the relevant innodb parameters from our config file:

innodb_additional_mem_pool_size = 20M
innodb_buffer_pool_size = 24000M
innodb_data_home_dir = /var/lib/mysql/inno
innodb_data_file_path = data:1G:autoextend
innodb_log_group_home_dir = /var/lib/mysql/log/inno
innodb_log_file_size = 2000M
innodb_log_files_in_group = 2
innodb_log_buffer_size = 8M
innodb_flush_log_at_trx_commit = 1
innodb_autoextend_increment = 32
#innodb_status_file
innodb_thread_concurrency = 8
innodb_lock_wait_timeout = 120
#innodb_force_recovery = 1
innodb_flush_method = O_DIRECT
innodb_rollback_on_timeout
#skip-innodb_doublewrite
#skip-innodb_adaptiv_hash_index
innodb_file_per_table
innodb_open_files = 20000

And for binary logging:
log-bin = /var/lib/mysql/log/bin/binlog
max_binlog_size = 250M
binlog-format = STATEMENT

How to repeat:
Not able to repeat on a consistent basis. Even on a slave that errors out with this message, we are able to start the slave and the transaction will complete successfully.

Thank you for the report.

I can not repeat same error message with only InnoDB tables: always get meaningful " 1598: Binary logging not possible. Message: Transaction level 'READ-UNCOMMITTED' in InnoDB is not safe for binlog mode 'STATEMENT'"

Please find a query which produces this error, find which TRANSACTION ISOLATION LEVEL you use when error occurs (SELECT @@tx_isolation;) and provide the query and output of SHOW CREATE TABLE for all underlying tables.

My default transaction level is REPEATABLE-READ.

Here is a sample of one of the SQL statements exactly like the failure we had. The only difference is the source table name:

insert into creative_iobudget_monthly_local(buyer_entity_id,io_id,line_item_id,campaign_id,creative_id,adv_learn_type,is_adjustment,imps,clicks,amt_paid_to_seller,roi_value,ymdh,id) select buyer_entity_id,io_id,line_item_id,campaign_id,creative_id,adv_learn_type,is_adjustment,imps,clicks,amt_paid_to_seller,roi_value,date_format(ymdh, '%Y-%m-01 00:00:00'),id from creative_iobudget_g08081223 where load_attempt=1 order by ymdh,id on duplicate key update creative_iobudget_monthly_local.imps = creative_iobudget_monthly_local.imps + VALUES(imps),creative_iobudget_monthly_local.clicks = creative_iobudget_monthly_local.clicks + VALUES(clicks),creative_iobudget_monthly_local.amt_paid_to_seller = creative_iobudget_monthly_local.amt_paid_to_seller + VALUES(amt_paid_to_seller),creative_iobudget_monthly_local.roi_value = creative_iobudget_monthly_local.roi_value + VALUES(roi_value);

This is the definition of creative_iobudget_g08081223:
CREATE TABLE IF NOT EXISTS `creative_iobudget_g08081817` (
  `buyer_entity_id` bigint(20) NOT NULL DEFAULT '0',
  `io_id` bigint(20) NOT NULL DEFAULT '0',
  `line_item_id` bigint(20) NOT NULL DEFAULT '0',
  `campaign_id` bigint(20) NOT NULL DEFAULT '0',
  `creative_id` bigint(20) NOT NULL DEFAULT '0',
  `adv_learn_type` char(1) NOT NULL DEFAULT '',
  `is_adjustment` tinyint(4) NOT NULL DEFAULT '0',
  `imps` bigint(20) NOT NULL DEFAULT '0',
  `clicks` int(11) NOT NULL DEFAULT '0',
  `amt_paid_to_seller` decimal(22,9) NOT NULL DEFAULT '0.000000000',
  `roi_value` decimal(22,9) NOT NULL DEFAULT '0.000000000',
  `ymdh` datetime NOT NULL,
  `id` int(11) NOT NULL,
  `hash_code` bigint(20) NOT NULL,
  `journal_line_id` int(11) NOT NULL,
  `recommended_partition` tinyint(4) NOT NULL,
  `load_attempt` tinyint(4) NOT NULL,
  PRIMARY KEY (`journal_line_id`),
  KEY `id` (`id`),
  KEY `ymdh` (`ymdh`,`id`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1 ROW_FORMAT=COMPACT;

And the definition for creative_iobudget_monthly_local:
CREATE TABLE `creative_iobudget_monthly_local` (
  `ymdh` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
  `id` int(10) unsigned NOT NULL DEFAULT '0',
  `checkpoint` smallint(6) DEFAULT NULL,
  `creative_id` bigint(20) NOT NULL DEFAULT '0',
  `campaign_id` bigint(20) NOT NULL DEFAULT '0',
  `buyer_entity_id` bigint(20) NOT NULL DEFAULT '0',
  `io_id` bigint(20) NOT NULL DEFAULT '0',
  `line_item_id` bigint(20) NOT NULL DEFAULT '0',
  `adv_learn_type` char(1) NOT NULL,
  `is_adjustment` tinyint(4) NOT NULL DEFAULT '0',
  `imps` bigint(20) NOT NULL DEFAULT '0',
  `amt_paid_to_seller` decimal(22,9) NOT NULL DEFAULT '0.000000000',
  `clicks` int(11) NOT NULL DEFAULT '0',
  `roi_value` decimal(22,9) NOT NULL DEFAULT '0.000000000',
  `apex_flag` tinyint(4) NOT NULL DEFAULT '2',
  `data_cost` decimal(22,9) NOT NULL DEFAULT '0.000000000',
  `data_revenue` decimal(22,9) NOT NULL DEFAULT '0.000000000',
  PRIMARY KEY (`ymdh`,`id`),
  KEY `ix_cbm_ymdh_creative` (`ymdh`,`creative_id`),
  KEY `ix_cbm_ymdh_campaign` (`ymdh`,`campaign_id`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1 ROW_FORMAT=COMPACT /*!50100 PARTITION BY RANGE (TO_DAYS(ymdh)) (PARTITION p2007q3 VALUES LESS THAN (733315) ENGINE = InnoDB, PARTITION p2007q4 VALUES LESS THAN (733407) ENGINE = InnoDB, PARTITION p_week_00_2008 VALUES LESS THAN (733412) ENGINE = InnoDB, PARTITION p_week_01_2008 VALUES LESS THAN (733419) ENGINE = InnoDB, PARTITION p_week_02_2008 VALUES LESS THAN (733426) ENGINE = InnoDB, PARTITION p_week_03_2008 VALUES LESS THAN (733433) ENGINE = InnoDB, PARTITION p_week_04_2008 VALUES LESS THAN (733440) ENGINE = InnoDB, PARTITION p_week_05_2008 VALUES LESS THAN (733447) ENGINE = InnoDB, PARTITION p_week_06_2008 VALUES LESS THAN (733454) ENGINE = InnoDB, PARTITION p_week_07_2008 VALUES LESS THAN (733461) ENGINE = InnoDB, PARTITION p_week_08_2008 VALUES LESS THAN (733468) ENGINE = InnoDB, PARTITION p_week_09_2008 VALUES LESS THAN (733475) ENGINE = InnoDB, PARTITION p_week_10_2008 VALUES LESS THAN (733482) ENGINE = InnoDB, PARTITION p_week_11_2008 VALUES LESS THAN (733489) ENGINE = InnoDB, PARTITION p_week_12_2008 VALUES LESS THAN (733496) ENGINE = InnoDB, PARTITION p_week_13_2008 VALUES LESS THAN (733503) ENGINE = InnoDB, PARTITION p_week_14_2008 VALUES LESS THAN (733510) ENGINE = InnoDB, PARTITION p_week_15_2008 VALUES LESS THAN (733517) ENGINE = InnoDB, PARTITION p_week_16_2008 VALUES LESS THAN (733524) ENGINE = InnoDB, PARTITION p_week_17_2008 VALUES LESS THAN (733531) ENGINE = InnoDB, PARTITION p_week_18_2008 VALUES LESS THAN (733538) ENGINE = InnoDB, PARTITION p_week_19_2008 VALUES LESS THAN (733545) ENGINE = InnoDB, PARTITION p_week_20_2008 VALUES LESS THAN (733552) ENGINE = InnoDB, PARTITION p_week_21_2008 VALUES LESS THAN (733559) ENGINE = InnoDB, PARTITION p_week_22_2008 VALUES LESS THAN (733566) ENGINE = InnoDB, PARTITION p_week_23_2008 VALUES LESS THAN (733573) ENGINE = InnoDB, PARTITION p_week_24_2008 VALUES LESS THAN (733580) ENGINE = InnoDB, PARTITION p_week_25_2008 VALUES LESS THAN (733587) ENGINE = InnoDB, PARTITION p_week_26_2008 VALUES LESS THAN (733594) ENGINE = InnoDB, PARTITION p_week_27_2008 VALUES LESS THAN (733601) ENGINE = InnoDB, PARTITION p_week_28_2008 VALUES LESS THAN (733608) ENGINE = InnoDB, PARTITION p_week_29_2008 VALUES LESS THAN (733615) ENGINE = InnoDB, PARTITION p_week_30_2008 VALUES LESS THAN (733622) ENGINE = InnoDB, PARTITION p_week_31_2008 VALUES LESS THAN (733629) ENGINE = InnoDB, PARTITION p_week_32_2008 VALUES LESS THAN (733636) ENGINE = InnoDB, PARTITION p_week_33_2008 VALUES LESS THAN (733643) ENGINE = InnoDB, PARTITION p_week_34_2008 VALUES LESS THAN (733650) ENGINE = InnoDB, PARTITION p_week_35_2008 VALUES LESS THAN (733657) ENGINE = InnoDB, PARTITION p_week_36_2008 VALUES LESS THAN (733664) ENGINE = InnoDB, PARTITION p_week_37_2008 VALUES LESS THAN (733671) ENGINE = InnoDB, PARTITION p_week_38_2008 VALUES LESS THAN (733678) ENGINE = InnoDB, PARTITION p_week_39_2008 VALUES LESS THAN (733685) ENGINE = InnoDB, PARTITION p_week_40_2008 VALUES LESS THAN (733692) ENGINE = InnoDB, PARTITION p_week_41_2008 VALUES LESS THAN (733699) ENGINE = InnoDB, PARTITION p_week_42_2008 VALUES LESS THAN (733706) ENGINE = InnoDB, PARTITION p_week_43_2008 VALUES LESS THAN (733713) ENGINE = InnoDB, PARTITION p_week_44_2008 VALUES LESS THAN (733720) ENGINE = InnoDB, PARTITION p_week_45_2008 VALUES LESS THAN (733727) ENGINE = InnoDB, PARTITION p_week_46_2008 VALUES LESS THAN (733734) ENGINE = InnoDB, PARTITION p_week_47_2008 VALUES LESS THAN (733741) ENGINE = InnoDB, PARTITION p_week_48_2008 VALUES LESS THAN (733748) ENGINE = InnoDB, PARTITION p_week_49_2008 VALUES LESS THAN (733755) ENGINE = InnoDB, PARTITION p_week_50_2008 VALUES LESS THAN (733762) ENGINE = InnoDB, PARTITION p_week_51_2008 VALUES LESS THAN (733769) ENGINE = InnoDB, PARTITION p_week_52_2008 VALUES LESS THAN (733776) ENGINE = InnoDB) */

Thank you for the feedback.

I still can not repeat described behavior. Please try current version 5.1.26-rc and if problem still exists provide error log file.

Still trying to find a way to reproduce this consistenly. Tried changing innodb_open_files from 20000 to 10000. The servers were okay for about a day, and then the slaves stopped with the same error message.

One thing to add...During the course of data inserts/updates 9 different innodb tables are created as staging tables, and later dropped. Perhaps something with open files causing the issue?

I will also try looking at 5.1.26 as well.

Please, try to repeat with a newer version, 5.1.28, and inform about the results.

Trying 5.1.28 right now to reproduce the problem. I would still like to understand when these error messages occur, or what triggers them.

This is still happening after upgrading the server to version 5.1.28. This happened on the slave server:

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: ses0661
                  Master_User: replicant
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: binlog.000047
          Read_Master_Log_Pos: 146088139
               Relay_Log_File: relay-bin.007704
                Relay_Log_Pos: 248
        Relay_Master_Log_File: binlog.000047
             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: 1598
                   Last_Error: Error 'Binary logging not possible. Message: Statement-based format required for this statement, but not allowed by this combination of engines' on query. Default database: 'rpt_prod'. Query: 'insert into network_daily_local(entity_id,buyer_entity_id,buyer_io_id,buyer_line_item_id,seller_entity_id,seller_io_id,seller_line_item_id,size_id,pop_type_id,country_group_id,adv_learn_type,pub_learn_type,is_adjustment,apex_flag,imps,clicks,convs,amt_paid_to_seller,amt_received_from_buyer,amt_paid_to_broker,roi_value,roi_cost,incremental_ltv,ymdh,id) select entity_id,buyer_entity_id,buyer_io_id,buyer_line_item_id,seller_entity_id,seller_io_id,seller_line_item_id,size_id,pop_type_id,country_group_id,adv_learn_type,pub_learn_type,is_adjustment,apex_flag,imps,clicks,convs,amt_paid_to_seller,amt_received_from_buyer,amt_paid_to_broker,roi_value,roi_cost,incremental_ltv,date_format(ymdh, '%Y-%m-%d 00:00:00'),id from network_g08100000c where load_attempt=1 order by ymdh,id on duplicate key update network_daily_local.imps = n
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 10220
              Relay_Log_Space: 146084278
              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: 1598
               Last_SQL_Error: Error 'Binary logging not possible. Message: Statement-based format required for this statement, but not allowed by this combination of engines' on query. Default database: 'rpt_prod'. Query: 'insert into network_daily_local(entity_id,buyer_entity_id,buyer_io_id,buyer_line_item_id,seller_entity_id,seller_io_id,seller_line_item_id,size_id,pop_type_id,country_group_id,adv_learn_type,pub_learn_type,is_adjustment,apex_flag,imps,clicks,convs,amt_paid_to_seller,amt_received_from_buyer,amt_paid_to_broker,roi_value,roi_cost,incremental_ltv,ymdh,id) select entity_id,buyer_entity_id,buyer_io_id,buyer_line_item_id,seller_entity_id,seller_io_id,seller_line_item_id,size_id,pop_type_id,country_group_id,adv_learn_type,pub_learn_type,is_adjustment,apex_flag,imps,clicks,convs,amt_paid_to_seller,amt_received_from_buyer,amt_paid_to_broker,roi_value,roi_cost,incremental_ltv,date_format(ymdh, '%Y-%m-%d 00:00:00'),id from network_g08100000c where load_attempt=1 order by ymdh,id on duplicate key update network_daily_local.imps = n

Please advise as to the next course of action!!

Thank you for the feedback.

Please try to apply patch followed and provide error output: patch only prints additional information. I want to check what is broken.

$bzr diff
=== modified file 'sql/sql_base.cc'
--- sql/sql_base.cc     2008-09-03 14:45:40 +0000
+++ sql/sql_base.cc     2008-10-06 19:31:07 +0000
@@ -5069,12 +5069,18 @@
                "Statement cannot be logged to the binary log in"
                " row-based nor statement-based format");
     }
-    else if (thd->variables.binlog_format == BINLOG_FORMAT_STMT &&
+    else if ((thd->variables.binlog_format == BINLOG_FORMAT_STMT &&
              (flags_all_set & HA_BINLOG_STMT_CAPABLE) == 0)
+                                       || 1 == foo)
     {
+        char onstack[512];
+        sprintf(onstack, "Statement-based format required for this statement,"
+                                         " but not allowed by this combination of engines, "
+                                         "thd->variables.tx_isolation: %d, thd->variables.binlog_format: %d, flags_all_set: %d",
+                                         thd->variables.tx_isolation, thd->variables.binlog_format, flags_all_set);
       my_error((error= ER_BINLOG_LOGGING_IMPOSSIBLE), MYF(0),
-                "Statement-based format required for this statement,"
-                " but not allowed by this combination of engines");
+                                         onstack
+                               );
     }
     else if ((thd->variables.binlog_format == BINLOG_FORMAT_ROW ||
               thd->lex->is_stmt_unsafe()) &&

Slave aborted this morning. I previously applied patch to 5.1.28. This is the output from the mysql error log:

081008 13:14:28 [ERROR] Slave SQL: Error 'Binary logging not possible. Message: Statement-based format required for this statement, but not allowed by this combination of engines, thd->variables.tx_isolation: 2, thd->variables.binlog_format: 1, flags_all_set: 67208334' on query. Default database: 'rpt_prod'. Query: 'insert into network_iobudget_hourly_local(entity_id,buyer_entity_id,buyer_io_id,buyer_line_item_id,seller_entity_id,seller_io_id,seller_line_item_id,is_adjustment,apex_flag,imps,clicks,convs,amt_paid_to_seller,amt_received_from_buyer,amt_paid_to_broker,roi_value,roi_cost,incremental_ltv,ymdh,source_tag,id,hash_code,journal_line_id) select entity_id,buyer_entity_id,buyer_io_id,buyer_line_item_id,seller_entity_id,seller_io_id,seller_line_item_id,is_adjustment,apex_flag,imps,clicks,convs,amt_paid_to_seller,amt_received_from_buyer,amt_paid_to_broker,roi_value,roi_cost,incremental_ltv,ymdh,'g08100200',id,hash_code,journal_line_id from network_iobudget_g08100200 where load_attempt=1 order by ymdh,id on duplicate key update ne
081008 13:14:28 [Warning] Slave: Binary logging not possible. Message: Statement-based format required for this statement, but not allowed by this combination of engines, thd->variables.tx_isolation: 2, thd->variables.binlog_format: 1, flags_all_set: 67208334 Error_code: 1598

This error just occured on the master, and it was a simple update of one table only:

mysql> update creative_convs_daily_local set conversion_id = -997997997997 where is_adjustment = 1 and line_item_id = 500786;
 ERROR 1598 (HY000): Binary logging not possible. Message: Statement-based format required for this statement, but not allowed by this combination of engines, thd->variables.tx_isolation: 2, thd->variables.binlog_format: 1, flags_all_set: 67208334

This is the table definition:
mysql> show create table creative_convs_daily_local\G
*************************** 1. row ***************************
       Table: creative_convs_daily_local
Create Table: CREATE TABLE `creative_convs_daily_local` (
  `ymdh` datetime NOT NULL DEFAULT '0000-00-00 00:00:00',
  `id` int(10) unsigned NOT NULL DEFAULT '0',
  `checkpoint` smallint(6) DEFAULT NULL,
  `conversion_id` bigint(20) NOT NULL DEFAULT '0',
  `is_post_click` tinyint(4) NOT NULL DEFAULT '0',
  `buyer_entity_id` bigint(20) NOT NULL DEFAULT '0',
  `seller_entity_id` bigint(20) NOT NULL DEFAULT '0',
  `io_id` bigint(20) NOT NULL DEFAULT '0',
  `line_item_id` bigint(20) NOT NULL DEFAULT '0',
  `campaign_id` bigint(20) NOT NULL DEFAULT '0',
  `creative_id` bigint(20) NOT NULL DEFAULT '0',
  `country_group_id` smallint(6) NOT NULL DEFAULT '0',
  `size_id` smallint(6) NOT NULL DEFAULT '0',
  `adv_learn_type` char(1) NOT NULL DEFAULT '',
  `pub_learn_type` char(1) NOT NULL DEFAULT '',
  `is_adjustment` tinyint(4) NOT NULL DEFAULT '0',
  `pop_type_id` smallint(6) NOT NULL DEFAULT '0',
  `category_id` int(11) NOT NULL DEFAULT '0',
  `product_id` int(11) NOT NULL DEFAULT '0',
  `landing_page_id` int(11) NOT NULL DEFAULT '0',
  `convs` int(11) NOT NULL DEFAULT '0',
  `revenue` decimal(22,9) NOT NULL DEFAULT '0.000000000',
  `units` int(11) NOT NULL DEFAULT '0',
  `incremental_ltv` decimal(22,9) NOT NULL DEFAULT '0.000000000',
  `apex_flag` tinyint(4) NOT NULL DEFAULT '2',
  `data_cost` decimal(22,9) NOT NULL DEFAULT '0.000000000',
  `data_revenue` decimal(22,9) NOT NULL DEFAULT '0.000000000',
  PRIMARY KEY (`ymdh`,`id`),
  KEY `ix_ccsdl_buyer_ymdh` (`buyer_entity_id`,`ymdh`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1 ROW_FORMAT=COMPACT /*!50100 PARTITION BY RANGE (TO_DAYS(ymdh)) (PARTITION p2007q3 VALUES LESS THAN (733315) ENGINE = InnoDB, PARTITION p2007q4 VALUES LESS THAN (733407) ENGINE = InnoDB, PARTITION p_week_00_2008 VALUES LESS THAN (733412) ENGINE = InnoDB, PARTITION p_week_02_2008 VALUES LESS THAN (733426) ENGINE = InnoDB, PARTITION p_week_04_2008 VALUES LESS THAN (733440) ENGINE = InnoDB, PARTITION p_week_06_2008 VALUES LESS THAN (733454) ENGINE = InnoDB, PARTITION p_week_08_2008 VALUES LESS THAN (733468) ENGINE = InnoDB, PARTITION p_week_10_2008 VALUES LESS THAN (733482) ENGINE = InnoDB, PARTITION p_week_12_2008 VALUES LESS THAN (733496) ENGINE = InnoDB, PARTITION p_week_14_2008 VALUES LESS THAN (733510) ENGINE = InnoDB, PARTITION p_week_16_2008 VALUES LESS THAN (733524) ENGINE = InnoDB, PARTITION p_week_18_2008 VALUES LESS THAN (733538) ENGINE = InnoDB, PARTITION p_week_20_2008 VALUES LESS THAN (733552) ENGINE = InnoDB, PARTITION p_week_22_2008 VALUES LESS THAN (733566) ENGINE = InnoDB, PARTITION p_week_24_2008 VALUES LESS THAN (733580) ENGINE = InnoDB, PARTITION p_week_26_2008 VALUES LESS THAN (733594) ENGINE = InnoDB, PARTITION p_week_28_2008 VALUES LESS THAN (733608) ENGINE = InnoDB, PARTITION p_week_30_2008 VALUES LESS THAN (733622) ENGINE = InnoDB, PARTITION p_week_32_2008 VALUES LESS THAN (733636) ENGINE = InnoDB, PARTITION p_week_34_2008 VALUES LESS THAN (733650) ENGINE = InnoDB, PARTITION p_week_36_2008 VALUES LESS THAN (733664) ENGINE = InnoDB, PARTITION p_week_38_2008 VALUES LESS THAN (733678) ENGINE = InnoDB, PARTITION p_week_40_2008 VALUES LESS THAN (733692) ENGINE = InnoDB, PARTITION p_week_42_2008 VALUES LESS THAN (733706) ENGINE = InnoDB, PARTITION p_week_44_2008 VALUES LESS THAN (733720) ENGINE = InnoDB, PARTITION p_week_46_2008 VALUES LESS THAN (733734) ENGINE = InnoDB, PARTITION p_week_48_2008 VALUES LESS THAN (733748) ENGINE = InnoDB, PARTITION p_week_50_2008 VALUES LESS THAN (733762) ENGINE = InnoDB, PARTITION p_week_52_2008 VALUES LESS THAN (733776) ENGINE = InnoDB) */
1 row in set (0.00 sec)

Thank you for the feedback.

We need some time to think about how to consistently repeat the problem/what to check also.

Repeatable test case below. Note this happens with innodb tables that are partitioned!

Start up a mysql server : mysqld --log-bin --binlog-format=STATEMENT --console

Create a partitioned table:
CREATE TABLE test1
(
  id smallint not null,
  primary key (id)
) engine=innodb
partition by range (id)
(
  partition p1 values less than (2),
  partition p2 values less than (4),
  partition p3 values less than (10)
);

flush tables;
insert into test1 values (1),(2),(3);
quit;

In another concurrent session:
set transaction isolation level read committed;
select * from test1;

Start a new session and connect to db:
mysql> set transaction isolation level repeatable read;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into test1 values (8);
ERROR 1598 (HY000): Binary logging not possible. Message: Statement-based format
 required for this statement, but not allowed by this combination of engines
mysql>
mysql> flush tables;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into test1 values (1);
Query OK, 1 row affected (0.00 sec)

It appears that this statement will fail until flush tables is called.

It is belived that the culprit is in how the table flags are set. In the case of a pure innodb table (non partitioned) then tx_isolation of the current thread is used to determine if statement based format is allowed.  With the partition handler, the table flag is checked only on table open. So if the very first statement that runs after a table is opened is a SELECT statement, then no insert, delete, update statements will work.

Thank you for the feedback.

I still can not repeat described behavior.

You wrote:

In another concurrent session:
set transaction isolation level read committed;
select * from test1;

Start a new session and connect to db:
mysql> set transaction isolation level repeatable read;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into test1 values (8);

Just to be sure: do you issue "set transaction isolation level repeatable read;" and "insert into test1 values (8);" in the same session?

The trick is that the table file handle should not be open:

SESSION #1
----------
1. FLUSH TABLES;
2. SET TRANSACTION ISOLATION READ COMMITTED;
3. SELECT * FROM test1;

Do not close this session to the db. Start a new concurrent session:

SESSION #2
----------
1. SET TRANSACTION ISOLATION LEVEL REPEATABLE READ;
2. INSERT INTO test1 VALUES(7);

Session 2 will fail. When session #1 has to open the table, the partition handler code will call the underlying storage engines table_flags() method and cache the state in the m_table_flags var.

I am proposing a patch for the partition engine so that it does not cache the table_flags:

--- sql/ha_partition.h      2008-10-18 10:36:28.000000000 +0000
+++ sql/ha_partition.h      2008-10-18 10:46:56.000000000 +0000
@@ -698,8 +698,7 @@
     index scan module.
     (NDB)
   */
-  virtual ulonglong table_flags() const
-  { return m_table_flags; }
+  ulonglong table_flags() const;
 
   /*
     This is a bitmap of flags that says how the storage engine

--- sql/ha_partition.cc     2008-10-18 10:36:02.000000000 +0000
+++ sql/ha_partition.cc     2008-10-18 16:55:23.000000000 +0000
@@ -5573,6 +5573,15 @@
 }
 
 
+ulonglong ha_partition::table_flags() const
+{
+  longlong ha_table_flags;
+  
+  ha_table_flags= (ulong)m_file[0]->ha_table_flags();
+  return m_table_flags | ha_table_flags;
+}
+
+
 void ha_partition::print_error(int error, myf errflag)
 {
   DBUG_ENTER("ha_partition::print_error");

Let me know if this looks okay. My minimal testing shows that it works.

Thank you for the feedback.

Finally verified as described.

Test case for MySQL test suite:

$cat bug39084.test
--source include/have_log_bin.inc
--source include/have_innodb.inc

set session transaction isolation level repeatable read;

CREATE TABLE test1
(
  id smallint not null,
  primary key (id)
) engine=innodb
partition by range (id)
(
  partition p1 values less than (2),
  partition p2 values less than (4),
  partition p3 values less than (10)
);

flush tables;
insert into test1 values (1),(2),(3);

FLUSH TABLES;
SET TRANSACTION ISOLATION LEVEL READ COMMITTED;
SELECT * FROM test1;

connect (addconroot, localhost, root,,);
connection addconroot;

SET TRANSACTION ISOLATION LEVEL REPEATABLE READ;
INSERT INTO test1 VALUES(7);

$cat bug39084-master.opt
--binlog-format=STATEMENT

This shows that table flags is not static between open and close for a handler, which partitioning assumes, the patch is in the right direction, but I will try to remove the m_table_flags completely, since it cannot be trusted.

I will instead enforce that all partition handlers have the same table flags when initializing partitions and when opening a partitioned table, and always use the first partition for checking the table flags.

Note that InnoDB decides table flags on a per-statement basis, so caching the flags inside partition is not a good idea, since they might change with the next statement.

Also, the table flags are only requested at the beginning of the statement, and the server caches the value for the duration of the statement, so there is no need for the partition engine to handle the caching internally.

Bug is not repeatable without partitions.

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/57296

2679 Mattias Jonsson	2008-10-29
      Bug#39084: Getting intermittent errors with statement-based binary logging
      
      Problem was that partitioning cached the table flags.
      These flags could change due to TRANSACTION LEVEL changes.
      
      Solution was to remove the cache and always return the table flags
      from the first partition (if the handler was initialized).

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/57371

2679 Mattias Jonsson	2008-10-29
      Bug#39084: Getting intermittent errors with statement-based binary logging
      
      Problem was that partitioning cached the table flags.
      These flags could change due to TRANSACTION LEVEL changes.
      Solution was to remove the cache and always return the table flags
      from the first partition (if the handler was initialized).

Hello,

I have the same problem over here running 
- windows vista 64
- mysql 5.1.29
- odbc 5.15

It used to work running earlier server versions I assume that was e.g. 5.1.28

The application is adding records towards a table, when this happens. I do not know yet if it hapens first record or not, but it does occur almost immediately.

Do not had time yet to see if I can work arround this, or that I have to go back to 5.2.28,

Sincerely,

Louis

Hello,

I have the same problem over here running 
- windows vista 64
- mysql 5.1.29
- odbc 5.15

It used to work running earlier server versions I assume that was e.g. 5.1.28

The application is adding records towards a table, when this happens. I do not know yet if it hapens first record or not, but it does occur almost immediately.

Do not had time yet to see if I can work arround this, or that I have to go back to 5.2.28,

Sincerely,

Louis

Hello,

Partha / Mattias,

Can you please indicate when a windows 64 binnary including the fix will become available?

Unless this is within days I have to go back to 5.1.28

Sincerely,

Louis

pushed into mysql-5.1-bugteam and mysql-6.0-bugteam

Pushed into 6.0.8-alpha  (revid:mattias.jonsson@sun.com-20081029202004-8lwjf3mw8fc9zuh8) (version source revid:mattias.jonsson@sun.com-20081106061815-rub56lesg18z5ens) (pib:5)

Pushed into 5.1.30  (revid:mattias.jonsson@sun.com-20081029202004-8lwjf3mw8fc9zuh8) (version source revid:mattias.jonsson@sun.com-20081106062907-gkpe2vr84le6c7wm) (pib:5)

Documented in the 5.1.30 and 6.0.8 changelogs as follows:

        Changing the transaction isolation level while replicating partitioned
        InnoDB tables could cause statement-based logging to fail.

5.1 fix will appear in 5.1.31 per mail from Joro. Adjusted changelog entry accordingly.

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/61268

2732 Mattias Jonsson	2008-12-10
      post push fix for test case for bug#39084.

pushed the fixed test to mysql-5.1-bugteam and mysql-6.0-bugteam.

(i.e. not running partition_innodb_stmt when not having partitioning)

Pushed into 5.1.31 (revid:joro@sun.com-20090115053147-tx1oapthnzgvs1ro) (version source revid:azundris@mysql.com-20081230114838-cn52tu180wcrvh0h) (merge vers: 5.1.31) (pib:6)

Pushed into 5.1.31-ndb-6.2.17 (revid:tomas.ulin@sun.com-20090119095303-uwwvxiibtr38djii) (version source revid:tomas.ulin@sun.com-20090115073240-1wanl85vlvw2she1) (merge vers: 5.1.31-ndb-6.2.17) (pib:6)

Pushed into 5.1.31-ndb-6.3.21 (revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (version source revid:tomas.ulin@sun.com-20090119104956-guxz190n2kh31fxl) (merge vers: 5.1.31-ndb-6.3.21) (pib:6)

Pushed into 5.1.31-ndb-6.4.1 (revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (version source revid:tomas.ulin@sun.com-20090119144033-4aylstx5czzz88i5) (merge vers: 5.1.31-ndb-6.4.1) (pib:6)

Pushed into 6.0.10-alpha (revid:joro@sun.com-20090119171328-2hemf2ndc1dxl0et) (version source revid:azundris@mysql.com-20081230114916-c290n83z25wkt6e4) (merge vers: 6.0.9-alpha) (pib:6)