PXB-3302: GTID of the last change output truncated in Xtrabackup back…

…up log

https://perconadev.atlassian.net/browse/PXB-3302

Problem:
--------
If the number of GTID sets are absolutely large on a MySQL instance, the output
“GTID of the last change” in the Xtrabackup log is truncated compared to the
full output in xtrabackup_binlog_info and xtrabackup_info

Analysis:
---------
The new error logging framework had limitation of 8192 characters and anything
above is truncated.

A string buf is formed and later passed to default implementaion of error logging.
log_write_errstream().

See log_sink_trad():
     if (output_buffer != nullptr) {
        if (msg_len < output_buffer->data.data_buffer.length)
          output_buffer->data.data_buffer.length = msg_len;
        else  // truncate message to buffer-size (and leave space for '\0')
          msg_len = output_buffer->data.data_buffer.length - 1;

Fix:
----
Since xtrabackup dont use any other configurable loggers, we can avoid this output_buffer,
and directly log to stderr.

sql/server_component/log_sink_trad.cc

@@ -285,11 +285,6 @@ int log_sink_trad(void *instance [[maybe_unused]], log_line *ll) {
  }
 
  {
- char internal_buff[LOG_BUFF_MAX];
- size_t buff_size = sizeof(internal_buff);
- char *buff_line = internal_buff;
- size_t len;
-
  if (!(out_types & LOG_ITEM_LOG_LABEL)) {
  label = (prio == ERROR_LEVEL) ? "ERROR" : log_label_from_prio(prio);
  label_len = strlen(label);
@@ -303,7 +298,11 @@ int log_sink_trad(void *instance [[maybe_unused]], log_line *ll) {
  iso_timestamp = buff_local_time;
  iso_len = strlen(buff_local_time);
  }
-
+#ifndef XTRABACKUP
+ char internal_buff[LOG_BUFF_MAX];
+ size_t buff_size = sizeof(internal_buff);
+ char *buff_line = internal_buff;
+ size_t len;
  /*
  WL#11009 adds "error identifier" as a field in square brackets
  that directly precedes the error message. As a result, new
@@ -344,6 +343,13 @@ int log_sink_trad(void *instance [[maybe_unused]], log_line *ll) {
 
  // write log-event to log-file
  log_write_errstream(buff_line, len);
+#else
+ fprintf(stderr, "%.*s %u [%.*s] [MY-%06u] [%.*s] %.*s\n", (int)iso_len,
+ iso_timestamp, thread_id, (int)label_len, label, errcode,
+ (int)subsys_len, subsys, (int)msg_len, msg);
+ fflush(stderr);
+
+#endif /* !XTRABACKUP */
  }
  }
 

storage/innobase/xtrabackup/test/suites/binlog/gtid.sh

@@ -35,3 +35,48 @@ if ! egrep -q '^mysql-bin.[0-9]+[[:space:]]+[0-9]+[[:space:]]+[a-f0-9:-]+$' \
 then
  die "Cannot find GTID coordinates in xtrabackup_binlog_info"
 fi
+
+#
+# PXB-3302 : Test if PXB logs GTID string > 8192 characters
+#
+
+
+sql1="SELECT UUID();"
+sql2="SET GTID_NEXT=;"
+sql3="BEGIN;COMMIT;"
+
+iterations=250
+for (( i=1; i<=$iterations; i++ ))
+do
+ uuid=`$MYSQL $MYSQL_ARGS -BN -e "$sql1"`
+ sql2="SET GTID_NEXT='$uuid:1';"
+ $MYSQL $MYSQL_ARGS -e "$sql2; $sql3"
+done
+
+GTID_FROM_SQL=$($MYSQL $MYSQL_ARGS -BN -e "SELECT JSON_UNQUOTE(JSON_EXTRACT(LOCAL, '$.gtid_executed')) AS gtid_executed FROM performance_schema.log_status" | tr -d '\\n')
+
+LOGFILE=$topdir/backup.log
+rm -rf $topdir/backup
+xtrabackup --backup --target-dir=$topdir/backup 2>&1 | tee $LOGFILE
+
+# Search for the line containing "GTID of the last change"
+line=$(grep "GTID of the last change" "$LOGFILE")
+
+# Check if the line was found
+if [ -z "$line" ]; then
+ echo "Error: 'GTID of the last change' not found in the $LOGFILE"
+ exit 1
+else
+ # Extract the GTID without single quotes
+ GTID_FROM_ERRORLOG=$(echo "$line" | awk -F"GTID of the last change '" '{print $2}' | cut -d"'" -f1)
+
+ # Print the result
+ if [ "$GTID_FROM_ERRORLOG" = "$GTID_FROM_SQL" ]; then
+ echo "GTID MATCHED"
+ else
+ echo "GTID MISMATCH"
+ echo "GTID_FROM_SQL is $GTID_FROM_SQL"
+ echo "GTID_FROM_ERRORLOG is $GTID_FROM_ERRORLOG"
+ exit 1
+ fi
+fi