[MDEV-8734] mysqlbinlog --start-position isn't bigint Created: 2015-09-03  Updated: 2015-11-17  Resolved: 2015-11-17

Status: Closed
Project: MariaDB Server
Component/s: Scripts & Clients
Affects Version/s: 10.0.21
Fix Version/s: 10.1.9

Type: Bug Priority: Major
Reporter: Daniel Black Assignee: Oleksandr Byelkin
Resolution: Fixed Votes: 0
Labels: client, upstream
Environment:

rhel6


Issue Links:
Relates
relates to MDEV-8746 max_binlog_size was exceeded Closed
Sprint: 10.1.9-3

 Description   

having 18G + binlogs probably isn't the best move however if mysqld supports them so should the client tools.

# mysqlbinlog --start-position 18844480604 mysql-bin.000061
Warning: option 'start-position': unsigned value 18844480604 adjusted to 4294967295
 
 
# mysqlbinlog --version
mysqlbinlog Ver 3.3 for Linux at x86_64
 
# yum info MariaDB-client.x86_64
 
Name        : MariaDB-client
Arch        : x86_64
Version     : 10.0.21
Release     : 1.el6
Size        : 49 M
Repo        : installed
From repo   : mariadb
Summary     : MariaDB: a very fast and robust SQL database server
URL         : http://mariadb.org
License     : GPL
Description : MariaDB: a very fast and robust SQL database server



 Comments   
Comment by Elena Stepanova [ 2015-09-03 ]

Hi Daniel,
Do you know whether it's already been filed upstream? If not, are you planning to do so?

You must have a really huge transaction to have this binlog position, given that the max value for max_binlog_size is ~18 times less...

Comment by Daniel Black [ 2015-09-03 ]

haven't looked upstream yet.

log-slave-update and a start slave sql_thread until relay_log ....

Seems the limit got exceeded

| max_binlog_size                          | 104857600            |
 
-rw-rw---- 1 mysql mysql   107362623 Aug 28 13:13 mysql-bin.000057
-rw-rw---- 1 mysql mysql   104866589 Aug 28 13:13 mysql-bin.000058
-rw-rw---- 1 mysql mysql   105813602 Aug 28 13:14 mysql-bin.000059
-rw-rw---- 1 mysql mysql   105470582 Aug 28 13:14 mysql-bin.000060
-rw-rw---- 1 mysql mysql 35721262759 Sep  3 12:30 mysql-bin.000061
-rw-rw---- 1 mysql mysql        1952 Aug 28 13:14 mysql-bin.index
 
 mysql]# tail  mysql-bin.index
/var/lib/mysql/mysql-bin.000052
/var/lib/mysql/mysql-bin.000053
/var/lib/mysql/mysql-bin.000054
/var/lib/mysql/mysql-bin.000055
/var/lib/mysql/mysql-bin.000056
/var/lib/mysql/mysql-bin.000057
/var/lib/mysql/mysql-bin.000058
/var/lib/mysql/mysql-bin.000059
/var/lib/mysql/mysql-bin.000060
/var/lib/mysql/mysql-bin.000061

Comment by Elena Stepanova [ 2015-09-03 ]

Is it possible that there was such a huge transaction?
My point is, maybe we have a bug around max_binlog_size (regardless the initial mysqlbinlog issue).

Comment by Daniel Black [ 2015-09-04 ]

no, it was mixed replication and lots of small transactions. Yes it looks like a max_binlog_size bug. start slave sql_thread until relay_log=.... is what was used on this node. I was replaying a few days of relay logs into galera as a replication slave as a test.

Comment by Daniel Black [ 2015-09-04 ]

elenst did you want a separate bug for the max_binlog_size being exceeded?

Comment by Elena Stepanova [ 2015-09-04 ]

danblack, if you don't mind filing it, it would be nice, thanks. I was going to try to reproduce it, but I can easily get distracted and forget, with a separate bug it has much better chances.

Comment by Elena Stepanova [ 2015-09-04 ]

Back to the initial problem, apparently it's not mysqlbinlog-specific, but the protocol limitation (for COM_BINLOG_DUMP).
It looks even worse with change master to...:

MariaDB [test]> change master to master_log_pos = 4294967296, master_log_file='wheezy-64-bin.000001';
Query OK, 0 rows affected (0.44 sec)
 
MariaDB [test]> start slave;
Query OK, 0 rows affected (0.00 sec)

No warnings, no nothing, but

                Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Client requested master to start replication from impossible position; the first event 'wheezy-64-bin.000001' at 0, the last event read from 'wheezy-64-bin.000001' at 4, the last b

Note at 0. That's how master interpreted the request:

                   13 Query     SELECT binlog_gtid_pos('wheezy-64-bin.000001',4294967296)
                   13 Binlog Dump       Log: 'wheezy-64-bin.000001'  Pos: 0

Compare:

MariaDB [test]> change master to master_log_pos = 4294967295, master_log_file='wheezy-64-bin.000001';
Query OK, 0 rows affected (0.33 sec)
 
MariaDB [test]> start slave;
Query OK, 0 rows affected (0.00 sec)

                Last_IO_Error: Got fatal error 1236 from master when reading data from binary log: 'Client requested master to start replication from impossible position; the first event 'wheezy-64-bin.000001' at 4294967295, the last event read from 'wheezy-64-bin.000001' at 4, the last byte read from 'wheezy-64-bin.000001' at 4.'

                   14 Query     SELECT binlog_gtid_pos('wheezy-64-bin.000001',4294967295)
                   14 Binlog Dump       Log: 'wheezy-64-bin.000001'  Pos: 4294967295

Comment by Elena Stepanova [ 2015-09-04 ]

All in all, I suppose the fix might be quite intrusive.
Also, I don't know if it makes any sense to re-report it upstream, most likely they'll suggest not to have such big binary logs...

Comment by Oleksandr Byelkin [ 2015-11-15 ]

The problem is that COM_BINLOG_DUMP accept only 4 bytes, so the command should be changed:

Ways:

  1. Make new command (bad idea IMHO)
  2. check if mariadb from other side and use a bit defferent format with 8 bytes parameter (pass 0xffffffff as position whan have to read bigger position)
  3. Add higher bytes of position at the end (can cause errors if we connected to old/non-mariadb server)
Comment by Daniel Black [ 2015-11-16 ]

4. Implement only for local files dump_local_log_entries and leave rest to upstream.

sql/sql_parse.cc
87f9ad372 (unknown                    2002-08-21 22:04:22 +0300 1715)       /* TODO: The following has to be changed to an 8 byte integer */

Comment by Oleksandr Byelkin [ 2015-11-16 ]

There is decision to fix only local operation.

Comment by Oleksandr Byelkin [ 2015-11-16 ]

revision-id: dcdf0b49f3362ac4da9ff6e8de88432b021d7105 (mariadb-10.1.8-54-gdcdf0b4)
parent(s): 0dfa0eef596ee677b55976793d632dc9b36928c7
committer: Oleksandr Byelkin
timestamp: 2015-11-16 15:41:09 +0100
message:

MDEV-8734 mysqlbinlog --start-position isn't bigint

fix it only for local operations.

Comment by Oleksandr Byelkin [ 2015-11-16 ]

Hmmm... the problem is that I can't get so big binlog to test (I saw description above but I am probably not so advanced with binlogs to repeat).

Comment by Daniel Black [ 2015-11-17 ]

I've no idea how I managed to do the original either, however 248 bytes is the header on each binlog file so strip and concatenate:

# cp mysql-bin.000899 ~/
# for a in mysql-bin.0009[0-5]* ; do echo $a; dd if=$a skip=1 bs=248 of=~/mysql-bin.000899 conv=notrunc oflag=append; done
# cd ~/
# ls -la
-rw-r-----   1 root  root  6435578709 Nov 17 07:02 mysql-bin.000899
# mysqlbinlog mysql-bin.000899 | grep '^# at'
....
# at 6435577915
# at 6435577959
# at 6435578031
# at 6435578091
# at 6435578122
# at 6435578166
# at 6435578253
# at 6435578631
# at 6435578662
#  ./usr/bin/mysqlbinlog --base64-output=decode-rows --start-position 6435578122 --stop-position 6435578631 mysql-bin.000899
Warning: option 'start-position': unsigned value 6435578122 adjusted to 4294967295
/*!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 /*!*/;
ERROR: Error in Log_event::read_log_event(): 'Found invalid event in binary log', data_len: 574240058, event_type: 115
ERROR: Could not read entry at offset 4294967295: Error in log format or read error.
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

If you give me a link to the right cento6 rpm build for the client I'll do some testing on it.

Comment by Oleksandr Byelkin [ 2015-11-17 ]

I've found other way: single statement treated as one transaction also, so having inserting from the table to the table in Aria and row binlog I gon 7Gb binlog.

My fix works:

bell@bell-ThinkPad:~/maria/git/server/mysql-test/var/mysqld.1/data$ ../../../../client/mysqlbinlog --start-position=8086618554  binlog.000004 
/*!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
#151117 11:01:31 server id 1  end_log_pos 249 	Start: binlog v 4, server v 10.1.9-MariaDB-debug-log created 151117 11:01:31
BINLOG '
+/pKVg8BAAAA9QAAAPkAAAAAAAQAMTAuMS45LU1hcmlhREItZGVidWctbG9nAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAA3QAEGggAAAAICAgCAAAACgoKAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAEEwQAAP0WX1g=
'/*!*/;
# at 8086618554
#151117 11:40:53 server id 1  end_log_pos 3791651327 	Query	thread_id=3	exec_time=2518	error_code=0
SET TIMESTAMP=1447756853/*!*/;
SET @@session.pseudo_thread_id=3/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1342177280/*!*/;
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.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
COMMIT
/*!*/;
# at 8086618623
#151117 11:40:53 server id 1  end_log_pos 3791651367 	Rotate to binlog.000005  pos: 4
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
bell@bell-ThinkPad:~/maria/git/server/mysql-test/var/mysqld.1/data$ 

Comment by Sergei Golubchik [ 2015-11-17 ]

ok to push.

I'd say, thought "limitation of the client-server protocol" instead of "maximum supported by remote operation", to make it clear that this is not the mysqlbinlog issue.

Generated at Thu Feb 08 07:29:22 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.