MySQL Bugs: #95008: applying binary log doesn't work with blackhole engine tables

Bug #95008	applying binary log doesn't work with blackhole engine tables
Submitted:	12 Apr 2019 13:00	Modified:	17 Apr 2019 13:55
Reporter:	Thomas Benkert	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S3 (Non-critical)
Version:	5.6.43 - 8.0.15	OS:	Linux (CentOS 7)
Assigned to:		CPU Architecture:	x86

Description:
My goal was to do a point in time recovery for one specific table. To speed up the process, I converted all other tables to blackhole engine tables (it doesn't matter, but if you're interested, the detailed process is described here: https://dba.stackexchange.com/questions/224985/point-in-time-recovery-not-working-with-bla... ).

I want to recover table tid_m_shop_productgroup, but when I apply the binary log, there's an error stating:

ERROR 1032 (HY000) at line 58: Can't find record in 'productSpecsWorkflows'

although the table productSpecsWorkflows uses the blackhole engine. When I don't use blackhole engine tables, the binary log applies without errors but takes ages.

The binlog format is set to MIXED, but the trouble causing statement is in ROW format. When I decode it, the statement is

UPDATE `flydbcom`.`productSpecsWorkflows`
WHERE
  @1='210244'
  @2='["cutting","stitching"]'
  @3=NULL
  @4=NULL
  @5=1
SET
  @1='210244'
  @2='["cutting","cross-folding","stitching"]'
  @3=NULL
  @4=NULL
  @5=1

How to repeat:
----
-- The schema you have to create:
----

/*!40101 SET @OLD_SQL_MODE=@@SQL_MODE, SQL_MODE='NO_AUTO_VALUE_ON_ZERO' */;
CREATE SCHEMA IF NOT EXISTS flydbcom;
USE flydbcom;

DROP TABLE IF EXISTS `productSpecsWorkflows`;
CREATE TABLE `productSpecsWorkflows` (
  `productSpec` varchar(100) NOT NULL,
  `workflow` varchar(255) NOT NULL DEFAULT '',
  `quantityMin` int(11) DEFAULT NULL,
  `quantityMax` int(11) DEFAULT NULL,
  `weighting` int(11) NOT NULL DEFAULT '1',
  PRIMARY KEY (`productSpec`),
  KEY `productSpecQuantities` (`productSpec`)
) ENGINE=BLACKHOLE DEFAULT CHARSET=utf8;

DROP TABLE IF EXISTS `tid_m_shop_productgroup`;
CREATE TABLE `tid_m_shop_productgroup` (
  `translationId` int(11) NOT NULL DEFAULT '0',
  `content` text,
  `language` varchar(2) NOT NULL DEFAULT '',
  `clientId` int(11) NOT NULL DEFAULT '0',
  `translated` smallint(1) DEFAULT NULL,
  `created` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00' COMMENT 'Erstellungsdatum',
  `modified` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP COMMENT 'Aenderungsdatum',
  PRIMARY KEY (`translationId`,`language`,`clientId`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

/*!40101 SET SQL_MODE=@OLD_SQL_MODE */;

----
-- Save this shortened binary log in a file:
----

/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#181206 23:16:55 server id 102  end_log_pos 120 CRC32 0x1cdc7cdd    Start: binlog v 4, server v 5.6.27-log created 181206 23:16:55
BINLOG '
158JXA9mAAAAdAAAAHgAAAAAAAQANS42LjI3LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAd18
3Bw=
'/*!*/;
# at 206749567
#181207  0:00:44 server id 101  end_log_pos 206749653 CRC32 0xf6d2c92c  Query   thread_id=2277437194    exec_time=115   error_code=0
SET TIMESTAMP=1544137244/*!*/;
SET @@session.pseudo_thread_id=2277437194/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1073741824/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
#181207  0:02:31 server id 101  end_log_pos 220215508 CRC32 0x6da6a564  Query   thread_id=2277419809    exec_time=42    error_code=0
SET TIMESTAMP=1544137351/*!*/;
SET @@session.sql_mode=524288/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
BEGIN
/*!*/;
# at 220215508
#181207  0:02:31 server id 101  end_log_pos 220215584 CRC32 0x98d80159  Table_map: `flydbcom`.`productSpecsWorkflows` mapped to number 838344
# at 220215584
#181207  0:02:31 server id 101  end_log_pos 220215712 CRC32 0xa0b963fe  Update_rows: table id 838344 flags: STMT_END_F

#BINLOG '
#h6oJXBNlAAAATAAAACA5IA0AAMjKDAAAAAEACGZseWRiY29tABVwcm9kdWN0U3BlY3NXb3JrZmxv
#d3MABQ8PAwMDBCwB/QIMWQHYmA==
#h6oJXB9lAAAAgAAAAKA5IA0AAMjKDAAAAAEAAgAF///sBgAyMTAyNDQXAFsiY3V0dGluZyIsInN0
#aXRjaGluZyJdAQAAAOwGADIxMDI0NCcAWyJjdXR0aW5nIiwiY3Jvc3MtZm9sZGluZyIsInN0aXRj
#aGluZyJdAQAAAP5juaA=
#'/*!*/;
# at 220215712
#181207  0:02:31 server id 101  end_log_pos 220215743 CRC32 0x18dfc06e  Xid = 6231167500
COMMIT/*!*/;
# at 220215743
#181207  0:02:31 server id 101  end_log_pos 220215806 CRC32 0x80c72c3d  Query   thread_id=2277419809    exec_time=42    error_code=0
SET TIMESTAMP=1544137351/*!*/;
BEGIN
/*!*/;
# at 220215806
#181207  0:02:31 server id 101  end_log_pos 220215882 CRC32 0xa4b4b8fa  Table_map: `flydbcom`.`productSpecsWorkflows` mapped to number 838344
# at 220215882
#181207  0:02:31 server id 101  end_log_pos 220216010 CRC32 0xebb13e86  Update_rows: table id 838344 flags: STMT_END_F

BINLOG '
h6oJXBNlAAAATAAAAEo6IA0AAMjKDAAAAAEACGZseWRiY29tABVwcm9kdWN0U3BlY3NXb3JrZmxv
d3MABQ8PAwMDBCwB/QIM+ri0pA==
h6oJXB9lAAAAgAAAAMo6IA0AAMjKDAAAAAEAAgAF///sBgAyMTAyNDQnAFsiY3V0dGluZyIsImNy
b3NzLWZvbGRpbmciLCJzdGl0Y2hpbmciXQEAAADsBgAyMTAyNDQXAFsiY3V0dGluZyIsInN0aXRj
aGluZyJdAQAAAIY+ses=
'/*!*/;
# at 220216010
#181207  0:02:31 server id 101  end_log_pos 220216041 CRC32 0x38f92bf6  Xid = 6231167502
COMMIT/*!*/;

----
-- Finally apply the binary log with
----

cat shortened_binary_log | mysql flydbcom

Suggested fix:
It should be possible to convert every table in a schema but one/few to engine blackhole, so that applying the binary log is a fast operation.

Please see:
https://dev.mysql.com/doc/refman/8.0/en/replication-features-blackhole.html

17.4.1.2 Replication and BLACKHOLE Tables
´´´´´
" When using row-based logging, updates and deletes to such tables are simply skipped—they are not written to the binary log. A warning is logged whenever this occurs.

For this reason we recommend when you replicate to tables using the BLACKHOLE storage engine that you have the binlog_format server variable set to STATEMENT, and not to either ROW or MIXED. "

Sorry, you seem to have misunderstoodd me. 
I am aware of this behaviour and it has nothing to do with this case. 

The issue here is that I have a schema with every table using InnodB engine. Binary logs therefore include all DML statements. Now someone wants to have a table from a certain point in time. So I restored a backup of the whole schema and converted all but one table to blackhole engine tables. I did this to speed up the applying of the binary logs, so that I get this one table with data at that certain point in time.

What I expect is, that while applying the binary logs, all other tables are essentially ignored. 

In the above case I would expect the error given when the binary log statement would be something like INSERT INTO tid_m_shop_productgroup SELECT something FROM productSpecsWorkflows WHERE foo = bar; 
But as you can see from the decoded binlog statement, it simply does an UPDATE statement on productSpecsWorkflows table, which uses the blackhole engine. Therefore I expect that applying the binary log does not raise an error on continue to run. Hopefully this clears things up.

Hi,

> WHERE
>  @1='210244'
>  @2='["cutting","stitching"]'
>  @3=NULL
>  @4=NULL
>  @5=1

This type of log is normally created if there is no PK in the table. For the "reproduction" of the issue you are offering the already created binlog, can you reproduce this with a properly designed table?

In any way this engine is not designed to be used with replication in any way other then to ignore data.. 

all best
Bogdan

Hello Bogdan,

as you can see from the table definition it has a proper primary key which is also used in the statement.

CREATE TABLE `productSpecsWorkflows` (
  `productSpec` varchar(100) NOT NULL,
  `workflow` varchar(255) NOT NULL DEFAULT '',
  `quantityMin` int(11) DEFAULT NULL,
  `quantityMax` int(11) DEFAULT NULL,
  `weighting` int(11) NOT NULL DEFAULT '1',
  PRIMARY KEY (`productSpec`),
  KEY `productSpecQuantities` (`productSpec`)
) ENGINE=BLACKHOLE DEFAULT CHARSET=utf8;

In my first tries of applying the binary log I also converted the productSpecsWorkflows table to InnoDB. Then the same error appeared with other tables. All the tables in the schema have a proper primary key, though. 

> In any way this engine is not designed to be used with replication in any way other then to ignore data..

But isn't that a use case that should definitely be supported? Recovering the table took me several hours, just to apply binary logs of a few hours. This could have been done in a few minutes. And what other use is the blackhole engine then for, other than just playing around with it?

Kind regards

Thomas

Hello Bogdan,

I just remembered, that I changed the primary key when converting to blackhole engine to avoid this bug: https://bugs.mysql.com/bug.php?id=53588

Before converting to blackhole, the primary key is specified as:

  PRIMARY KEY (`productSpec`,`workflow`)

Do you think that solving the other bug would solve this bug, too?

Hi Thomas,

Some data here is missing or I'm getting partially blind :D .. I do see the table structure that's not a problem but I don't see anywhere what is the actual statement that produced the mentioned binlog, the statement you say uses PK.

As for the other bug, I don't think solving that one will help with this one.

To get bact to statement. What is the exact update executed on master that was logged as this update failing on blackhole

all best
Bogdan

Oh, sorry, I meant the (decoded) binlog statement. What the original statement was, I unfortunately don't know and don't think I can find out.
I (wrongly) said it's using the PK because of the 5 columns in the WHERE clause and the table has just 5 columns.

Hi,

I'm thinking a bit more about this and I'm not 100% sure if blackhole should return error here or not so I'm actually verifying this and will let replication team make a final decision.

all best
Bogdan

mysql 8.0.15:

mysql [localhost:8015] {msandbox} (flydbcom) > BINLOG '
    '> h6oJXBNlAAAATAAAAEo6IA0AAMjKDAAAAAEACGZseWRiY29tABVwcm9kdWN0U3BlY3NXb3JrZmxv
    '> d3MABQ8PAwMDBCwB/QIM+ri0pA==
    '> h6oJXB9lAAAAgAAAAMo6IA0AAMjKDAAAAAEAAgAF///sBgAyMTAyNDQnAFsiY3V0dGluZyIsImNy
    '> b3NzLWZvbGRpbmciLCJzdGl0Y2hpbmciXQEAAADsBgAyMTAyNDQXAFsiY3V0dGluZyIsInN0aXRj
    '> aGluZyJdAQAAAIY+ses=
    '> '/*!*/;
ERROR 1032 (HY000): Can't find record in 'productSpecsWorkflows'