[MDEV-16372] ER_BASE64_DECODE_ERROR upon replaying binary log Created: 2018-06-01  Updated: 2020-10-06  Resolved: 2020-08-31

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.3
Fix Version/s: 10.1.48, 10.2.35, 10.3.26, 10.4.16, 10.5.7

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Andrei Elkin
Resolution: Fixed Votes: 1
Labels: mysqlbinlog, verbose

Attachments: File 10.3-fix_draft.diff    
Issue Links:
Duplicate
is duplicated by MDEV-10362 mysqlbinlog verbose output cannot be ... Closed
Relates
relates to MDEV-16370 row-based binlog events (updates by p... Closed

 Description   

Inspired by MDEV-16370

--source include/have_log_bin.inc
--source include/have_binlog_format_row.inc
 
create table t (a int) with system versioning;
insert into t values (1);
update t set a = 2 where a = 1;
flush logs;
drop table t;
--let $datadir= `select @@datadir`
 
--exec $MYSQL_BINLOG -v $datadir/master-bin.000001 | $MYSQL test
select * from t;
 
# Cleanup
drop table t;

10.3 c98e6d4b3d4d

ERROR 1575 (HY000) at line 82: Decoding of base64 string failed
mysqltest: At line 11: exec of '/data/bld/10.3/bin/mysqlbinlog --defaults-file=/data/bld/10.3/mysql-test/var/my.cnf --local-load=/data/bld/10.3/mysql-test/var/tmp -v /data/bld/10.3/mysql-test/var/mysqld.1/data//master-bin.000001 | /data/bld/10.3/bin/mysql --defaults-file=/data/bld/10.3/mysql-test/var/my.cnf test' failed, error: 256, status: 1, errno: 11



 Comments   
Comment by Aleksey Midenkov [ 2018-06-13 ]

Analysis

Comment by Aleksey Midenkov [ 2019-04-01 ]

Reproducible without System versioning:

--echo #
--echo # MDEV-16372 ER_BASE64_DECODE_ERROR upon replaying binary log with system table
--echo #
FLUSH BINARY LOGS;
CREATE TABLE t1 (pk INT PRIMARY KEY);
INSERT INTO t1 VALUES (1);
INSERT INTO t1 VALUES (1), (2) ON DUPLICATE KEY UPDATE pk= pk + 10;
 
--let $binlog = query_get_value(SHOW MASTER STATUS, File, 1)
 
FLUSH BINARY LOGS;
DROP TABLE t1;
--exec $MYSQL_BINLOG --verbose $datadir/$binlog | $MYSQL test
SELECT * FROM t1;
DROP TABLE t1;

Comment by Aleksey Midenkov [ 2019-04-01 ]

Attached rebased patch on later 10.3. Now it conflicts with copy_cache_to_file_wrapped() logic as comments are printed earlier in print_verbose(). Since copy_cache_to_... routine initiate BINLOG statement, they should also take care about terminating it. Now this logic is shared with print_verbose():

12015       if (!is_verbose)
12016         my_fprintf(file, fmt_delim, delimiter);

More details are here.

Comment by Daniel Black [ 2020-07-29 ]

Elkin is the https://github.com/MariaDB/server/pull/791 correct?

Comment by Andrei Elkin [ 2020-08-04 ]

danblack: Thanks for making it in front of my eyes! I am just back to duties and will look through the issue/patch within a couple of days.

Comment by Andrei Elkin [ 2020-08-15 ]

midenok: It took quite a while to receive an explicit review request which I'm handling. There's a good reason
to take another option to where to hold the verbose comments. I took the method from an upstream patch to do that in another (3rd) special cache. I hope you're fine with it, esp considering the idea just follows the orig architecture, and not least the patch indeed smaller. [Interestingly, the very same method is *now* repeated in a duplicate attempt MDEV-23077 ('bug01' part) to fix this issue, which I came to know few days back].

My plan is to test out 10.2 (and up) version of my current patch and then to request to review the two versions.
If you volunteer to review I would be happy. When not, I hope Sachin would do it (as yet another duplicate MDEV-10362's (ex-)owner).

Comment by Andrei Elkin [ 2020-08-27 ]

Sujatha, could you please review it.
There are three patches
c7a8a636e
12f3f01fb
78f67ea08
for 10.1,10.2 and 10.3 respectively.
10.4 and 10.5 don't have specifics to adopt the 10.3 version fine.

10.2 - 10.1 is caused by flashback d75d8631ed2d.
10.3 - 10.2 by Monty's refactoring e64184134a19, and partly - cache operation error reporting - by an upstream patch by your own hands d054027c4bfa which the Monty's patch seems to have relied upon. I mean the following hunk of 10.1 patch

--- a/client/mysqlbinlog.cc
+++ b/client/mysqlbinlog.cc
@@ -860,7 +860,8 @@ static bool print_base64(PRINT_EVENT_INFO *print_event_info, Log_event *ev)
   ev->print(result_file, print_event_info);
   return
     print_event_info->head_cache.error == -1 ||
-    print_event_info->body_cache.error == -1;
+    print_event_info->body_cache.error == -1 ||
+    print_event_info->tail_cache.error == -1;

does not exist in 10.3 'cos of e64184134a1's decision. Read that commit's log:

    - Write_on_release_cache() rewritten so that we can detect errors
      on flush. Not depending on automatic release anymore.

And actually means your early patch's

d054027c4bfa (Sujatha Sivakumar 2013-03-28  63)   if(cache->error == -1)
d054027c4bfa (Sujatha Sivakumar 2013-03-28  64)     DBUG_RETURN(1);

(see git annotate for mf_iocache2.c).

Comment by Sujatha Sivakumar (Inactive) [ 2020-08-31 ]

Hello Andrei,

Thank you for working on this issue.
Minor code alignment specific comment is provided on 10.1 patch, it is available on github.

The rest of the changes look good.

Thank you.

Comment by Andrei Elkin [ 2020-08-31 ]

For merging please notice there are 3 commits for 10.1, 10.2 and 10.3+
feac078f15c
6112a0f93d1
caa35f8e25c
respectively, pushed to the branches.
At merging 10.1->10.2 and 10.2->10.3 therefore choose --ours.

Generated at Thu Feb 08 08:28:25 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.