MySQL Bugs: #71324: mysqlbinlog parses binary logs wrong with tinyint unsigned values

Bug #71324	mysqlbinlog parses binary logs wrong with tinyint unsigned values
Submitted:	9 Jan 2014 12:34	Modified:	13 Jan 2014 8:55
Reporter:	FRANCISCO BORDENAVE	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Utilities: Binlog Events	Severity:	S3 (Non-critical)
Version:	5.5.30, 5.5.35	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	mysqlbinlog, row based, Tinyint

Description:
When parsing a binary log with mysqlbinlog values stored in tinyint unsinged that falls between 128 and 255 are showed erroneously in the output. 
mysql> insert into a values(NULL,129,rand()*500);
Query OK, 1 row affected (0.00 sec)

BINLOG '
xYHNUhMMHQAAKgAAAM0YAAAAACgAAAAAAAEABHRlc3QAAWEAAwMBAwAG
xYHNUhcMHQAAJwAAAPQYAAAAACgAAAAAAAEAA//4BAAAAIHzAQAA
'/*!*/;
### INSERT INTO test.a
### SET
### @1=4
### @2=-127 (129)
### @3=499

How to repeat:
Easy example: 
mysql> select version();
+-----------------+
| version() |
+-----------------+
| 5.5.35-33.0-log |
+-----------------+
1 row in set (0.00 sec)
mysql> show global variables like '%binlog_format%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | ROW |
+---------------+-------+
1 row in set (0.01 sec)

mysql> create table a (col_ int not null auto_increment primary key, col_2 tinyint(1) unsigned ,col_3 int ); 
Query OK, 0 rows affected (0.06 sec)

mysql> insert into a values(NULL,126,rand()*500);
Query OK, 1 row affected (0.00 sec)

mysql> insert into a values(NULL,127,rand()*500);
Query OK, 1 row affected (0.00 sec)

mysql> insert into a values(NULL,128,rand()*500);
Query OK, 1 row affected (0.00 sec)

mysql> insert into a values(NULL,129,rand()*500);
Query OK, 1 row affected (0.00 sec)

mysql> insert into a values(NULL,255,rand()*500);
Query OK, 1 row affected (0.00 sec)

mysql> select * from a;
+------+-------+-------+
| col_ | col_2 | col_3 |
+------+-------+-------+
| 1 | 126 | 192 |
| 2 | 127 | 267 |
| 3 | 128 | 260 |
| 4 | 129 | 499 |
| 5 | 255 | 170 |
+------+-------+-------+
5 rows in set (0.00 sec)

BINLOG '
9X7NUhMMHQAAKgAAAF4UAAAAACcAAAAAAAEABHRlc3QAAWEAAwMBAwAG
9X7NUhcMHQAAJwAAAIUUAAAAACcAAAAAAAEAA//4BQAAAH5RAQAA
'/*!*/;
### INSERT INTO test.a
### SET
### @1=5
### @2=126
### @3=337
# at 5253
#140108 18:38:13 server id 7436 end_log_pos 5280 Xid = 586
COMMIT/*!*/;
# at 5280
#140108 18:38:16 server id 7436 end_log_pos 5348 Query thread_id=401 exec_time=0 error_code=0
SET TIMESTAMP=1389199096/*!*/;
BEGIN
/*!*/;
# at 5348
# at 5390
#140108 18:38:16 server id 7436 end_log_pos 5390 Table_map: `test`.`a` mapped to number 39
#140108 18:38:16 server id 7436 end_log_pos 5429 Write_rows: table id 39 flags: STMT_END_F

BINLOG '
+H7NUhMMHQAAKgAAAA4VAAAAACcAAAAAAAEABHRlc3QAAWEAAwMBAwAG
+H7NUhcMHQAAJwAAADUVAAAAACcAAAAAAAEAA//4BgAAAH9yAQAA
'/*!*/;
### INSERT INTO test.a
### SET
### @1=6
### @2=127
### @3=370
# at 5429
#140108 18:38:16 server id 7436 end_log_pos 5456 Xid = 587
COMMIT/*!*/;
# at 5456
#140108 18:38:20 server id 7436 end_log_pos 5524 Query thread_id=401 exec_time=0 error_code=0
SET TIMESTAMP=1389199100/*!*/;
BEGIN
/*!*/;
# at 5524
# at 5566
#140108 18:38:20 server id 7436 end_log_pos 5566 Table_map: `test`.`a` mapped to number 39
#140108 18:38:20 server id 7436 end_log_pos 5605 Write_rows: table id 39 flags: STMT_END_F

BINLOG '
/H7NUhMMHQAAKgAAAL4VAAAAACcAAAAAAAEABHRlc3QAAWEAAwMBAwAG
/H7NUhcMHQAAJwAAAOUVAAAAACcAAAAAAAEAA//4BwAAAIBQAQAA
'/*!*/;
### INSERT INTO test.a
### SET
### @1=7
### @2=-128 (128)
### @3=336
# at 5605
#140108 18:38:20 server id 7436 end_log_pos 5632 Xid = 588
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
BINLOG '
xYHNUhMMHQAAKgAAAM0YAAAAACgAAAAAAAEABHRlc3QAAWEAAwMBAwAG
xYHNUhcMHQAAJwAAAPQYAAAAACgAAAAAAAEAA//4BAAAAIHzAQAA
'/*!*/;
### INSERT INTO test.a
### SET
### @1=4
### @2=-127 (129)
### @3=499
# at 6388
#140108 18:50:13 server id 7436 end_log_pos 6415 Xid = 717
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
BINLOG '
MoLNUhMMHQAAKgAAAH0ZAAAAACgAAAAAAAEABHRlc3QAAWEAAwMBAwAG
MoLNUhcMHQAAJwAAAKQZAAAAACgAAAAAAAEAA//4BQAAAP+qAAAA
'/*!*/;
### INSERT INTO test.a
### SET
### @1=5
### @2=-1 (255)
### @3=170
# at 6564
#140108 18:52:02 server id 7436 end_log_pos 6591 Xid = 774
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

Suggested fix:
Seems mysqlbinlog is converting values in comments from unsigned tinyint into signed one byte integer  so in the case of 129 is b10000001 which is -127 if you convert to glibc int. 
Using correct conversion will avoid confusion, the replication works correctly so it looks like a representation problem.

mysqlbinlog from 5.6.15 is also affected:

C:\Program Files\MySQL\MySQL Server 5.6\bin>mysql -uroot -proot -P3314 test
Warning: Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 44
Server version: 5.6.15-log MySQL Community Server (GPL)

Copyright (c) 2000, 2013, 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> flush logs;
Query OK, 0 rows affected (0.21 sec)

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

mysql> drop table a;
Query OK, 0 rows affected (0.17 sec)

mysql>  create table a (col_ int not null auto_increment primary key, col_2 tiny
int(1) unsigned ,col_3 int );
Query OK, 0 rows affected (0.49 sec)

mysql> insert into a values(NULL,129,rand()*500);
Query OK, 1 row affected (0.11 sec)

mysql> insert into a values(NULL,255,rand()*500);
Query OK, 1 row affected (0.08 sec)

mysql> show master status;
+------------------+----------+--------------+------------------+---------------
----+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_
Set |
+------------------+----------+--------------+------------------+---------------
----+
| pc-PC-bin.000018 |      796 |              |                  |
    |
+------------------+----------+--------------+------------------+---------------
----+
1 row in set (0.00 sec)

mysql> exit
Bye

C:\Program Files\MySQL\MySQL Server 5.6\bin>mysqlbinlog --base64-output=DECODE-R
OWS --verbose -uroot -proot "c:\ProgramData\MySQL\MySQL Server 5.6\data\pc-PC-bi
n.000018"
Warning: Using a password on the command line interface can be insecure.
/*!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
#140109 15:25:57 server id 1  end_log_pos 120 CRC32 0x709084e4  Start: binlog v
4, server v 5.6.15-log created 140109 15:25:57
# Warning: this binlog is either in use or was not closed properly.
# at 120
#140109 15:26:14 server id 1  end_log_pos 234 CRC32 0x938a1176  Query   thread_i
d=44    exec_time=0     error_code=0
use `test`/*!*/;
SET TIMESTAMP=1389273974/*!*/;
SET @@session.pseudo_thread_id=44/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.uniq
ue_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1344274432/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/
;
/*!\C cp866 *//*!*/;
SET @@session.character_set_client=36,@@session.collation_connection=36,@@sessio
n.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
DROP TABLE `a` /* generated by server */
/*!*/;
# at 234
#140109 15:26:17 server id 1  end_log_pos 408 CRC32 0x91545dec  Query   thread_i
d=44    exec_time=1     error_code=0
SET TIMESTAMP=1389273977/*!*/;
create table a (col_ int not null auto_increment primary key, col_2 tinyint(1) u
nsigned ,col_3 int )
/*!*/;
# at 408
#140109 15:26:19 server id 1  end_log_pos 480 CRC32 0xe755aa82  Query   thread_i
d=44    exec_time=0     error_code=0
SET TIMESTAMP=1389273979/*!*/;
BEGIN
/*!*/;
# at 480
#140109 15:26:19 server id 1  end_log_pos 526 CRC32 0xc3984012  Table_map: `test
`.`a` mapped to number 374
# at 526
#140109 15:26:19 server id 1  end_log_pos 571 CRC32 0xa39f3e8e  Write_rows: tabl
e id 374 flags: STMT_END_F
### INSERT INTO `test`.`a`
### SET
###   @1=1
###   @2=-127 (129)
###   @3=136
# at 571
#140109 15:26:19 server id 1  end_log_pos 602 CRC32 0xfeab6f3b  Xid = 896510
COMMIT/*!*/;
# at 602
#140109 15:26:20 server id 1  end_log_pos 674 CRC32 0xacac119a  Query   thread_i
d=44    exec_time=0     error_code=0
SET TIMESTAMP=1389273980/*!*/;
BEGIN
/*!*/;
# at 674
#140109 15:26:20 server id 1  end_log_pos 720 CRC32 0x3070095d  Table_map: `test
`.`a` mapped to number 374
# at 720
#140109 15:26:20 server id 1  end_log_pos 765 CRC32 0xe04fe1cf  Write_rows: tabl
e id 374 flags: STMT_END_F
### INSERT INTO `test`.`a`
### SET
###   @1=2
###   @2=-1 (255)
###   @3=301
# at 765
#140109 15:26:20 server id 1  end_log_pos 796 CRC32 0x84394ce1  Xid = 896511
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

So, we should clearly know that data are unsigned, what is the point to interpret them both ways in comments? This may lead to problem when output is used to reproduce row changes.

If we don't have enough metadata information to find out if data were really signed, may be we should add it?

Adding metadata might work but I think having the actual value stored in DB is better since the output can be used either to reproduce row changes (i.e. for moving data from mysql to another RDBMS) or for forensic analysis so even if this looks trivial it may lead to a wrong interpretation of values.

Hello Francisco,

Thank you for the bug report. 
Verified as described.

Thanks,
Umesh