From 35823af6d321a6f54b3759ba2d46a26a3103f588 Mon Sep 17 00:00:00 2001 From: Jaideep Karande Date: Thu, 25 Jun 2026 12:14:02 +0530 Subject: [PATCH] PS-11216: Timestamps needed in the GCS_DEBUG_TRACE file Every line written to GCS_DEBUG_TRACE now carries an ISO 8601 UTC timestamp with microsecond precision at the front of the line: [YYYY-MM-DDTHH:MM:SS.uuuuuuZ] [MYSQL_GCS_DEBUG] [GCS] --- .../r/gr_gcs_debug_trace_timestamps.result | 28 ++++++ .../t/gr_gcs_debug_trace_timestamps.test | 95 +++++++++++++++++++ .../include/mysql/gcs/gcs_logging_system.h | 8 +- .../src/interface/gcs_logging_system.cc | 39 ++++++++ 4 files changed, 164 insertions(+), 6 deletions(-) create mode 100644 mysql-test/suite/group_replication/r/gr_gcs_debug_trace_timestamps.result create mode 100644 mysql-test/suite/group_replication/t/gr_gcs_debug_trace_timestamps.test diff --git a/mysql-test/suite/group_replication/r/gr_gcs_debug_trace_timestamps.result b/mysql-test/suite/group_replication/r/gr_gcs_debug_trace_timestamps.result new file mode 100644 index 000000000000..70f779f02a4d --- /dev/null +++ b/mysql-test/suite/group_replication/r/gr_gcs_debug_trace_timestamps.result @@ -0,0 +1,28 @@ +include/group_replication.inc +Warnings: +Note #### Sending passwords in plain text without SSL/TLS is extremely insecure. +Note #### Storing MySQL user name or password information in the connection metadata repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START REPLICA; see the 'START REPLICA Syntax' in the MySQL Manual for more information. +[connection server1] + +# Step 1: Start Group Replication — GCS_DEBUG_TRACE must be created. +include/start_and_bootstrap_group_replication.inc + +# Step 2: Enable GCS_DEBUG_BASIC tracing +SET GLOBAL group_replication_communication_debug_options = "GCS_DEBUG_BASIC"; +include/assert.inc [Debug option is GCS_DEBUG_BASIC] + +# Step 3: verify ISO 8601 UTC timestamps(microsecond) in GCS_DEBUG_TRACE +include/wait_for_pattern_in_file.inc [\[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}Z\] \[MYSQL_GCS_DEBUG\] \[GCS\]] + +# Step 4: disable then re-enable tracing; timestamps must persist +SET GLOBAL group_replication_communication_debug_options = "GCS_DEBUG_NONE"; +SET GLOBAL group_replication_communication_debug_options = "GCS_DEBUG_ALL"; +include/assert_grep.inc [Timestamps persist after tracing re-enable] + +# Step 5: Verify Group Replication is still ONLINE. +include/assert.inc [Member is ONLINE after timestamp test] + +# Step 6: Cleanup. +SET GLOBAL group_replication_communication_debug_options = "GCS_DEBUG_NONE"; +include/stop_group_replication.inc +include/group_replication_end.inc diff --git a/mysql-test/suite/group_replication/t/gr_gcs_debug_trace_timestamps.test b/mysql-test/suite/group_replication/t/gr_gcs_debug_trace_timestamps.test new file mode 100644 index 000000000000..9583355ef1db --- /dev/null +++ b/mysql-test/suite/group_replication/t/gr_gcs_debug_trace_timestamps.test @@ -0,0 +1,95 @@ +################################################################################ +# PS-11216: Timestamps needed in the GCS_DEBUG_TRACE file +# +# This test case veritfy that every log written to GCS_DEBUG_TRACE carries a +# ISO 8601 UTC timestamp with microsecond precision, leading the line: +# [YYYY-MM-DDTHH:MM:SS.uuuuuuZ] [MYSQL_GCS_DEBUG] [GCS] +# +# Test steps: +# 1. Start Group Replication — GCS_DEBUG_TRACE must be created. +# 2. Enable tracing; let the consumer write a few lines. +# 3. Verify ISO 8601 UTC timestamps with microsecond precision. +# 4. Disable then re-enable; verify timestamps continue in new entries. +# 5. Verify Group Replication is still ONLINE. +# 6. Cleanup. +################################################################################ + +--source include/have_group_replication_plugin.inc +--let $rpl_skip_group_replication_start = 1 +--source include/group_replication.inc + +############################################################################## +# Step 1: Start Group Replication — GCS_DEBUG_TRACE is created. +############################################################################## + +--echo +--echo # Step 1: Start Group Replication — GCS_DEBUG_TRACE must be created. +--source include/start_and_bootstrap_group_replication.inc +--file_exists $MYSQLTEST_VARDIR/mysqld.1/data/GCS_DEBUG_TRACE + +############################################################################## +# Step 2: Enable tracing; let the consumer write a few lines. +############################################################################## +--echo +--echo # Step 2: Enable GCS_DEBUG_BASIC tracing +SET GLOBAL group_replication_communication_debug_options = "GCS_DEBUG_BASIC"; + +--let $assert_text = Debug option is GCS_DEBUG_BASIC +--let $assert_cond = "[SELECT @@GLOBAL.group_replication_communication_debug_options]" = "GCS_DEBUG_BASIC" +--source include/assert.inc + +############################################################################## +# Step 3: Verify ISO 8601 UTC timestamps with microsecond precision. +############################################################################## +--echo +--echo # Step 3: verify ISO 8601 UTC timestamps(microsecond) in GCS_DEBUG_TRACE + +# Wait until at least one timestamped line appears in the trace file. +--let $grep_pattern = \[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}Z\] \[MYSQL_GCS_DEBUG\] \[GCS\] +--let $grep_file = $MYSQLTEST_VARDIR/mysqld.1/data/GCS_DEBUG_TRACE +--source include/wait_for_pattern_in_file.inc + +############################################################################## +# Step 4: Disable then re-enable; verify timestamps continue in new entries. +############################################################################## +--echo +--echo # Step 4: disable then re-enable tracing; timestamps must persist + +# Record file size before the cycle so we can prove new entries were appended. +--let $size_before = `SELECT LENGTH(LOAD_FILE(CONCAT(@@datadir, 'GCS_DEBUG_TRACE')))` + +SET GLOBAL group_replication_communication_debug_options = "GCS_DEBUG_NONE"; +SET GLOBAL group_replication_communication_debug_options = "GCS_DEBUG_ALL"; + +# Wait until the file grows beyond the size recorded before the cycle. +--let $wait_condition = SELECT LENGTH(LOAD_FILE(CONCAT(@@datadir, 'GCS_DEBUG_TRACE'))) > $size_before +--source include/wait_condition.inc + +--let $assert_text = Timestamps persist after tracing re-enable +--let $assert_file = $MYSQLTEST_VARDIR/mysqld.1/data/GCS_DEBUG_TRACE +--let $assert_select = \[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}Z\] \[MYSQL_GCS_DEBUG\] \[GCS\] +--let $assert_count_condition = >= 1 +--source include/assert_grep.inc + +############################################################################## +# Step 5: Verify Group Replication is still ONLINE. +############################################################################## +--echo +--echo # Step 5: Verify Group Replication is still ONLINE. + +--let $assert_text = Member is ONLINE after timestamp test +--let $assert_cond = COUNT(*) = 1 FROM performance_schema.replication_group_members WHERE MEMBER_STATE = "ONLINE" +--source include/assert.inc + +############################################################################## +# Step 6: Cleanup. +############################################################################## +--echo +--echo # Step 6: Cleanup. + +SET GLOBAL group_replication_communication_debug_options = "GCS_DEBUG_NONE"; +--source include/stop_group_replication.inc + +--remove_file $MYSQLTEST_VARDIR/mysqld.1/data/GCS_DEBUG_TRACE + +--source include/group_replication_end.inc diff --git a/plugin/group_replication/libmysqlgcs/include/mysql/gcs/gcs_logging_system.h b/plugin/group_replication/libmysqlgcs/include/mysql/gcs/gcs_logging_system.h index 5954c3c8144f..85a13f95ed14 100644 --- a/plugin/group_replication/libmysqlgcs/include/mysql/gcs/gcs_logging_system.h +++ b/plugin/group_replication/libmysqlgcs/include/mysql/gcs/gcs_logging_system.h @@ -659,6 +659,7 @@ class Gcs_default_debugger { /** Add extra information as a message prefix. + [YYYY-MM-DDTHH:MM:SS.uuuuuuZ] [MYSQL_GCS_DEBUG] [GCS] We assume that there is room to accommodate it. Before changing this method, make sure the maximum buffer size will always have room to @@ -666,12 +667,7 @@ class Gcs_default_debugger { @return Return the size of appended information */ - inline size_t append_prefix(char *buffer) { - strcpy(buffer, GCS_DEBUG_PREFIX); - strcpy(buffer + GCS_DEBUG_PREFIX_SIZE, GCS_PREFIX); - - return GCS_DEBUG_PREFIX_SIZE + GCS_PREFIX_SIZE; - } + size_t append_prefix(char *buffer); /** Append information into a message such as end of line. diff --git a/plugin/group_replication/libmysqlgcs/src/interface/gcs_logging_system.cc b/plugin/group_replication/libmysqlgcs/src/interface/gcs_logging_system.cc index 94b86404aa9d..ed813b775936 100644 --- a/plugin/group_replication/libmysqlgcs/src/interface/gcs_logging_system.cc +++ b/plugin/group_replication/libmysqlgcs/src/interface/gcs_logging_system.cc @@ -37,6 +37,7 @@ #include "my_dir.h" #include "my_io.h" #include "my_sys.h" +#include "my_systime.h" #endif /* XCOM_STANDALONE */ #include "plugin/group_replication/libmysqlgcs/include/mysql/gcs/gcs_logging_system.h" @@ -337,6 +338,44 @@ enum_gcs_error Gcs_default_debugger::initialize() { enum_gcs_error Gcs_default_debugger::finalize() { return m_sink->finalize(); } +/* + Returns 0 for XCOM_STANDALONE because XCOM_STANDALONE excludes the MySQL + portability headers (my_systime.h, my_sys.h) needed by my_micro_time(). + + XCOM_STANDALONE is defined when XCom is built as a standalone library + for unit-testing the consensus protocol in isolation. +*/ +static size_t gcs_format_timestamp(char *buf [[maybe_unused]]) { +#ifdef XCOM_STANDALONE + return 0; +#else + const unsigned long long us = my_micro_time(); + const time_t sec = static_cast(us / 1000000); + const long usec = static_cast(us % 1000000); + struct tm tm_info; + if (gmtime_r(&sec, &tm_info) == nullptr) return 0; + int len = sprintf(buf, "[%04d-%02d-%02dT%02d:%02d:%02d.%06ldZ] ", + tm_info.tm_year + 1900, tm_info.tm_mon + 1, tm_info.tm_mday, + tm_info.tm_hour, tm_info.tm_min, tm_info.tm_sec, usec); + return (len > 0) ? static_cast(len) : 0; +#endif +} + +size_t Gcs_default_debugger::append_prefix(char *buffer) { + size_t base = 0; + + /* Timestamp leads the prefix so the final format is: + [YYYY-MM-DDTHH:MM:SS.uuuuuuZ] [MYSQL_GCS_DEBUG] [GCS] */ + size_t ts_len = gcs_format_timestamp(buffer); + base += ts_len; + + strcpy(buffer + base, GCS_DEBUG_PREFIX); + strcpy(buffer + base + GCS_DEBUG_PREFIX_SIZE, GCS_PREFIX); + base += GCS_DEBUG_PREFIX_SIZE + GCS_PREFIX_SIZE; + + return base; +} + /** Reference to the default debugger which is used internally by GCS and XCOM. */