MySQL Bugs: #62582: Bit Field column length in table map event in binary log for MySQL 5.5

Bug #62582	Bit Field column length in table map event in binary log for MySQL 5.5
Submitted:	30 Sep 2011 8:01	Modified:	24 Dec 2013 14:35
Reporter:	Ashish Kumar	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S2 (Serious)
Version:	5.5	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
We are working for Oracle GoldenGate for MySQL and use MySQL Binary log for
replication.
As per MySQL documentation,bit datatype is a bit-filed value and bit column
can be declared as column_name bit(bit_length). Bit field value is inserted
like a bit stream ; width of this bit stream can be from 1 to 64.

References:
http://dev.mysql.com/doc/refman/5.0/en/bit-field-values.html
http://dev.mysql.com/doc/refman/5.0/en/numeric-types.html

On investigating more, we found out that in addition to a bit pattern,MySQL
allows to enter bit column value as 0 or 1. If values entered are 0 and 1, we
find different behavior in MySQL Binary Log for MySQL 5.1 & MySQL 5.5
versions.

1) MySQL 5.1:
We get the correct data value and max data length in the binary log ( in
table map event ) and replication works properly.

2) MySQL 5.5:
For these values, We get the max data length as 0 in binary log ( in table
map event ) and the data value as empty and replication fails as a result.

How to repeat:
Use MySQL version 5.5

1) Create a table with a bit column.
drop database if exists ggsrc;
create database ggsrc;
drop table if exists ggsrc.emp;

CREATE  TABLE `ggsrc`.`emp` ( 
  `C26Bit` bit NULL 
); 

flush master;

2) Insert bit column value as 0 and 1.
INSERT INTO ggsrc.emp
VALUES 
( 
    0
); 

INSERT INTO ggsrc.emp
VALUES 
( 
    1
); 

Read the Table metadata from binary log table map event. Data column size comes as 0.

Suggested fix:

Upon more investigation, problem got more clear.
If we declare a bit column with bit field width that is not multiple of 8, we get the wrong data in the binary log.

For example,

CREATE  TABLE `ggsrc`.`emp` ( 
  `C26Bit` bit( 7 ) NULL 
); 

If the bit field width is not multiple of 8, and we try to insert any column value, we do not get correct column value and length in the binary log in MySQL 5.5.

INSERT INTO ggsrc.emp
VALUES 
( 
    b'1000'
); 

Does that mean in MySQL 5.5 bit column length is no longer 1 - 8 bytes in the binary log?

What you see (in non-strict SQL_mode) is simple truncation.  You will get a warning. Try:

INSERT INTO ggsrc.emp
VALUES 
( 
    0
); 
SHOW WARNINGS;

INSERT INTO ggsrc.emp
VALUES 
( 
    1
);
SHOW WARNINGS;

"1" here evauates to the binary representation of the '1' (ASCII) character - ie. "110001" (49 in decimal notation)

For that sake you may also

INSERT INTO ggsrc.emp
VALUES 
( 
    a
);
SHOW WARNINGS;

-- and what you trye to insert is b'1100001' (97 in decimal notation).

In non-strcit SQL_mode such insert will truncate (with a warning) exactly the same way as if you try to insert 'ashish' to a char(1) column. Only 'a' gets inserted.

This is how to do it:

INSERT INTO ggsrc.emp
VALUES 
( 
    b'1'
);
SHOW WARNINGS;

(and the pages you link to describe it actually.)

Peter
(not a MySQL person)

and BTW: why is the binary log relevant for the discussion here?

We read the binary log for replicating data. Our problem is not truncation. 
We do not get the data in binary log read the data from binary log 

mysql> CREATE  TABLE `ggsrc`.`emp` (
    ->   `C26Bit` bit(3) NULL
    -> );
Query OK, 0 rows affected (0.01 sec)

mysql> INSERT INTO ggsrc.emp
    -> VALUES
    -> (
    ->     b'1'
    -> );
Query OK, 1 row affected (0.00 sec)

mysql> show warnings;
Empty set (0.00 sec)

We read the binary log for replicating data. Our problem is not truncation. 
We do not get the data in binary log read the data from binary log 

mysql> CREATE  TABLE `ggsrc`.`emp` (
    ->   `C26Bit` bit(3) NULL
    -> );
Query OK, 0 rows affected (0.01 sec)

mysql> INSERT INTO ggsrc.emp
    -> VALUES
    -> (
    ->     b'1'
    -> );
Query OK, 1 row affected (0.00 sec)

mysql> show warnings;
Empty set (0.00 sec)

What is the value of binlog_format server variable in your case? 

I see the following with STATEMENT format:

macbook-pro:5.5 openxs$ bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.5.17-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> create table emp(c bit(7) null);
Query OK, 0 rows affected (0.05 sec)

mysql> insert into emp values (b'1000');
Query OK, 1 row affected (0.01 sec)

mysql> select hex(c) from emp;
+--------+
| hex(c) |
+--------+
| 8      |
+--------+
1 row in set (0.00 sec)

mysql> show master status\G
*************************** 1. row ***************************
            File: macbook-pro-bin.000003
        Position: 391
    Binlog_Do_DB: 
Binlog_Ignore_DB: 
1 row in set (0.00 sec)

mysql> show binlog events in 'macbook-pro-bin.000003'\G
*************************** 1. row ***************************
   Log_name: macbook-pro-bin.000003
        Pos: 4
 Event_type: Format_desc
  Server_id: 1
End_log_pos: 107
       Info: Server ver: 5.5.17-debug-log, Binlog ver: 4
*************************** 2. row ***************************
   Log_name: macbook-pro-bin.000003
        Pos: 107
 Event_type: Query
  Server_id: 1
End_log_pos: 201
       Info: use `test`; create table emp(c bit(7) null)
*************************** 3. row ***************************
   Log_name: macbook-pro-bin.000003
        Pos: 201
 Event_type: Query
  Server_id: 1
End_log_pos: 269
       Info: BEGIN
*************************** 4. row ***************************
   Log_name: macbook-pro-bin.000003
        Pos: 269
 Event_type: Query
  Server_id: 1
End_log_pos: 364
       Info: use `test`; insert into emp values (b'1000')
*************************** 5. row ***************************
   Log_name: macbook-pro-bin.000003
        Pos: 364
 Event_type: Xid
  Server_id: 1
End_log_pos: 391
       Info: COMMIT /* xid=18 */
5 rows in set (0.01 sec)

mysql> show variables like 'binlog%';
+-----------------------------------------+-----------+
| Variable_name                           | Value     |
+-----------------------------------------+-----------+
| binlog_cache_size                       | 32768     |
| binlog_direct_non_transactional_updates | OFF       |
| binlog_format                           | STATEMENT |
| binlog_stmt_cache_size                  | 32768     |
+-----------------------------------------+-----------+
4 rows in set (0.00 sec)

and I do not see any problem in the above.

I just want to explain the problem that we are facing with MySQL 5.5.
We work for Oracle Goldegate for MySQL. We use MySQL Binary logs to replicat the data. We support only ROW based logging for replication.
We read the events directly from the binary logs. For getting the metadata of the table participating in the transaction we read TableMap Event. This event precedes any event that represents DML operation such as Write, Update and Delete row events.
This event contains generic header followed by additional data header section and data section.
There is one section in the tablemap event called as Field Metadata.
Field metadata usually represents information pertaining to the size of the column metadata. This can be treated as pack length i.e total number bytes required to pack particular column values. These values are later used for reading appropriate bytes to get actual values.

In case of MySQL5.1, we are getting these values correct as below,

Bit column length Column Size(bytes)

1 - 8 1
9 - 16 2
17 - 24 3
25 - 32 4
33 - 40 5
...................................................
...................................................

But in MySQL 5.5 we are not getting these values correct.
For MySQL 5.5 getting values like below,

Bit column length Column Size(bytes)

1 - 7 0
8 1
9 - 15 1
16 2
17 - 23 2
24 3
25 - 31 4
...................................................
...................................................
So, we can see that in MySQL 5.5 we are getting the values correct only if we declare the bit-column size as multiple of a byte size, i.e. - 8, 16, 24, 32.. etc.

So, in case of bit column , if we dont get the correct numbers of bytes , that we have to read , in order to get the column value, we read wrong values. Since we wrong numbers of bytes, the next bytes that we read also gets wrong and the product fails to work after that.

Changing to more relevant subject line.

Now, this is more clear. But I still wonder what exact version of MySQL 5.5, 5.5.x, do you use?

I've executed the same statements:

create table tb1(c1 bit(5));
insert into tb1 values (b'10');
insert into tb1 values (b'0');

in 5.1.60 and in 5.5.17, with row based logging. Then I've checked table map events, type 13, using:

bin/mysqlbinlog --hexdump ...

In 5.1.60 I've got (for the first INSERT):

# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#      108 cf c6 89 4e   13   01 00 00 00   2c 00 00 00   34 01 00 00   00 00
#      11b 13 00 00 00 00 00 01 00  04 74 65 73 74 00 03 74 |.........test..t|
#      12b 62 31 00 01 10 02 05 00  01  |b1.......|
# 	Table_map: `test`.`tb1` mapped to number 19

And in 5.5.17:

# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#      109 75 c3 89 4e   13   01 00 00 00   2c 00 00 00   35 01 00 00   00 00
#      11c 30 00 00 00 00 00 01 00  04 74 65 73 74 00 03 74 |0........test..t|
#      12c 62 31 00 01 10 02 05 00  01  |b1.......|
# 	Table_map: `test`.`tb1` mapped to number 48

Note that the only difference in the dump of event itself is in the very first hex number, 13 (19 in hex) vs 30 (48 in hex). Everything else is the same.

Also the following command:

bin/mysqlbinlog --base64-output=DECODE-ROWS --verbose ...

was able to decode bit values correctly in both 5.1.60 and 5.5.17 case. So, mysqlbinlog itself has no problem to get correct value from the binary log, unlike software you create.

Question is: why are you sure there is a bug in the table map event in the binary log?

Thanks.
Below is the version information. We have used Community Server. We are configuring Enterprise server and then will test again .

mysql> show variables like '%version%';
+-------------------------+------------------------------+
| Variable_name           | Value                        |
+-------------------------+------------------------------+
| innodb_version          | 1.1.6                        |
| protocol_version        | 10                           |
| slave_type_conversions  |                              |
| version                 | 5.5.12-log                   |
| version_comment         | MySQL Community Server (GPL) |
| version_compile_machine | x86                          |
| version_compile_os      | Win64                        |
+-------------------------+------------------------------+
7 rows in set (0.00 sec)

Latest GA version is important, and this is 5.5.16. Please, check with it. 

Community or Enterprise should not matter that much.

We have investigated more on MySQL 5.5.8 and MySQL 5.5.15 Enterprise Server versions and the results are same. There is a difference in TableMap event's max_col_size in 5.1 and 5.5. Below is the hex dump of both for the same ddl/dml. The second last value in the hex dump refers to the max_col_size which is 00 in case of MySQL 5.5 which is incorrect. In case of MySQL 5.1 we are getting this value correct ( 01 ).

MySQL 5.1:

#111011 17:15:10 server id 1  end_log_pos 221 
# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#       af 46 2c 94 4e   13   01 00 00 00   2e 00 00 00   dd 00 00 00   00 00
#       c2 0f 00 00 00 00 00 00 00  05 67 67 76 61 6d 00 03 |.........ggvam..|
#       d2 65 6d 70 00 02 03 10 02  00 01 02  |emp........|
# 	Table_map: `ggvam`.`emp` mapped to number 15

MySQL 5.5:

# Position  Timestamp   Type   Master ID        Size      Master Pos    Flags 
#       b0 a6 26 94 4e   13   01 00 00 00   2e 00 00 00   de 00 00 00   00 00
#       c3 25 00 00 00 00 00 01 00  05 67 67 76 61 6d 00 03 |.........ggvam..|
#       d3 65 6d 70 00 02 03 10 02  05 00 02  |emp........|
# 	Table_map: `ggvam`.`emp` mapped to number 37

Code, which prints BIT field metadata is same in 5.1 and 5.5

Thank you for the feedback.

As you can see we could not repeat this issue internally using tools from MySQL distribution. Also I found no change in MySQL source code in this area. Therefore I close the report as "Can't repeat". Feel free to reopen it if you will be able to provide complete step-by-step test case, demonstrating the issue.