[MDEV-21851] Error in BINLOG_BASE64_EVENT is always error-logged as if it's done by the slave Created: 2020-03-01  Updated: 2021-09-06  Resolved: 2020-06-12

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.1, 10.2, 10.3, 10.4, 10.5
Fix Version/s: 10.5.4

Type: Bug Priority: Minor
Reporter: Andrei Elkin Assignee: Andrei Elkin
Resolution: Fixed Votes: 0
Labels: None


 Description   

In case of error a BINLOG '...' "pseudo"-query is logged into the error log prefixed
as if it's done by a slave applier thread. E.g 

2020-03-01 20:08:03 18 [ERROR]  Slave SQL: Could not execute Write_rows_v1 event

In this case it can be only a plain connection user so the apparent ambiguity needs
to be fixed.
Something like the following block

--- a/sql/sql_binlog.cc
 
+++ b/sql/sql_binlog.cc
 
@@ -210,7 +210,7 @@ void mysql_client_binlog_statement(THD* thd)
 
   size_t coded_len= 0, decoded_len= 0;
 
 
   rli= thd->rli_fake;
 
-  if (!rli && (rli= thd->rli_fake= new Relay_log_info(FALSE)))
 
+  if (!rli && (rli= thd->rli_fake= new Relay_log_info(FALSE, "BINLOG_BASE64_EVENT")))
 
     rli->sql_driver_thd= thd;
 
   if (!(rgi= thd->rgi_fake))
 
     rgi= thd->rgi_fake= new rpl_group_info(rli);

accompanied with changes in reporting function, like 

@@ -76,7 +71,8 @@ Slave_reporting_capability::report(loglevel level, int err_code,
 
   va_end(args);
 
 
   /* If the msg string ends with '.', do not add a ',' it would be ugly */
 
-  report_function("Slave %s: %s%s %s%sInternal MariaDB error code: %d",
 
+  report_function("%s %s: %s%s %s%sInternal MariaDB error code: %d",
 
+                  (current_thd && current_thd->rgi_fake) ? "" : "Slave",
 
                   m_thread_name, pbuff,
 
                   (pbuff[0] && *(strend(pbuff)-1) == '.') ? "" : ",",
 
                   (extra_info ? extra_info : ""), (extra_info ? ", " : ""),



 Comments   
Comment by Andrei Elkin [ 2020-03-02 ]

'Slave SQL' is the actual prefix that the initial description meant.

Comment by Andrei Elkin [ 2020-03-04 ]

The latest patch is pushed along with the XA ones to bb-10.5-MDEV_21469.

Comment by Sujatha Sivakumar (Inactive) [ 2020-03-05 ]

Hello Andrei,

Thank you for the patch.
Changes look good to me.

Comment by Roel Van de Paar [ 2021-09-06 ]

FYI, Notes like this can be seen:

10.6.5 9ac1ac006197c8979db1dc73f4e983f623e831e8 (Optimized)

 
21-09-06 20:33:48 4 [Note]  BINLOG_BASE64_EVENT: Rolling back unfinished transaction (no COMMIT or ROLLBACK in relay log). A probable cause is that the master died while writing the transaction to its binary log, thus rolled back too. Internal MariaDB error code: 0

When executing:

CREATE TABLE t2 (c INT,c2 INT,c3 INT);
 
SET AUTOCOMMIT=OFF;
 
DELETE FROM t2;
 
BINLOG ' VydmVA8BAAAAZwAAAGsAAAAAAAQANS41LjM2LTM0LjAtZGVidWctbG9nAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAABXJ2ZUEzgNAAgAEgAEBAQEEgAAVAAEGggAAAAICAgCAA==';

The latter BINLOG command is likely an FD event.

With thanks to sujatha.sivakumar for a very clear explanation of what is happening here.

Interestingly, whilst this happens on 10.2 to 10.6 on both optimized and debug builds, it does not happen on 10.7 optimized builds, but does on 10.7 debug builds. It also does not happen on MySQL. It would be interesting to find out why?

Generated at Thu Feb 08 09:10:17 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.