From 31abeff54f875105403eb72917663bc73c4847dc Mon Sep 17 00:00:00 2001 From: Prathamesh Hukkeri Date: Thu, 13 Aug 2026 17:07:27 +0530 Subject: [PATCH 1/3] MDEV-39307: Fix %f in audit plugin timestamp rendering zero microseconds The server_audit_timestamp_format %f specifier always rendered zero microseconds. The server downcast the precise time to seconds before passing it to audit plugins, and the plugin then re-fetched the time itself at write time. Pass the server's high-resolution time through the audit API instead: - extend mysql_event_general with general_time_microseconds (added in MYSQL_AUDIT_INTERFACE_VERSION 0x0304), keeping general_time in seconds for backward compatibility - mysql_audit_general_log now takes my_hrtime_t and forwards it without downcasting; the general (error/result/status) events fill general_time_microseconds from a single my_hrtime() call - the server_audit plugin uses event->general_time_microseconds for query log entries instead of re-fetching the time at write time Connection and table events carry no timestamp in the audit API, so the plugin keeps taking the time at event time for those entries. --- include/mysql/plugin_audit.h | 10 +++- include/mysql/plugin_audit.h.pp | 1 + .../plugins/r/server_audit_timestamp.result | 17 +++++- .../plugins/t/server_audit_timestamp.test | 47 +++++++++++++++- plugin/server_audit/server_audit.cc | 55 ++++++++----------- sql/log.cc | 2 +- sql/sql_audit.h | 19 ++++++- 7 files changed, 110 insertions(+), 41 deletions(-) diff --git a/include/mysql/plugin_audit.h b/include/mysql/plugin_audit.h index be83c7e02f73f..01842666bce88 100644 --- a/include/mysql/plugin_audit.h +++ b/include/mysql/plugin_audit.h @@ -29,7 +29,7 @@ extern "C" { #define MYSQL_AUDIT_CLASS_MASK_SIZE 1 -#define MYSQL_AUDIT_INTERFACE_VERSION 0x0303 +#define MYSQL_AUDIT_INTERFACE_VERSION 0x0304 /************************************************************************* @@ -69,6 +69,14 @@ struct mysql_event_general /* Added in version 0x303 */ unsigned int port; MYSQL_CONST_LEX_STRING database; + /* + Added in version 0x304. + + The time when the event occurred, in microseconds since the epoch. + general_time above keeps the second resolution for backward + compatibility. + */ + unsigned long long general_time_microseconds; }; diff --git a/include/mysql/plugin_audit.h.pp b/include/mysql/plugin_audit.h.pp index d0be440ecf759..bd8b2b36319d6 100644 --- a/include/mysql/plugin_audit.h.pp +++ b/include/mysql/plugin_audit.h.pp @@ -738,6 +738,7 @@ unsigned long long query_id; unsigned int port; MYSQL_CONST_LEX_STRING database; + unsigned long long general_time_microseconds; }; struct mysql_event_connection { diff --git a/mysql-test/suite/plugins/r/server_audit_timestamp.result b/mysql-test/suite/plugins/r/server_audit_timestamp.result index f1d1187702fe5..a2c237b827d54 100644 --- a/mysql-test/suite/plugins/r/server_audit_timestamp.result +++ b/mysql-test/suite/plugins/r/server_audit_timestamp.result @@ -156,7 +156,7 @@ set global server_audit_timestamp_format='T24=%T'; select 'fmt_t24'; fmt_t24 fmt_t24 -# 2l: Microseconds %f (always 000000 until MDEV-39307 is fixed) +# 2l: Microseconds %f render six zero-padded digits set global server_audit_timestamp_format='US=%f'; select 'fmt_usec'; fmt_usec @@ -179,7 +179,7 @@ FOUND 1 /OD=\d+\w+.*fmt_ord/ in ts_ext_specifiers.log FOUND 1 /STATIC-TEXT.*fmt_literal/ in ts_ext_specifiers.log FOUND 1 /\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.*fmt_iso/ in ts_ext_specifiers.log FOUND 1 /T24=\d{2}:\d{2}:\d{2}.*fmt_t24/ in ts_ext_specifiers.log -FOUND 1 /US=000000.*fmt_usec/ in ts_ext_specifiers.log +FOUND 1 /US=\d{6}.*fmt_usec/ in ts_ext_specifiers.log FOUND 1 /TZ=[+-]\d{4}.*fmt_tz/ in ts_ext_specifiers.log ######################################################################## # Section 3: All event types get custom timestamps @@ -343,6 +343,19 @@ FOUND 1 /PS=\d{8}.*persist_cycle1/ in ts_ext_persist.log FOUND 1 /PS=\d{8}.*persist_cycle2/ in ts_ext_persist.log FOUND 1 /P2=\d{8}.*persist_cycle3/ in ts_ext_persist.log ######################################################################## +# Section 10: Microsecond resolution of %f (MDEV-39307) +######################################################################## +set global server_audit_file_path='ts_ext_usec.log'; +set global server_audit_events='query'; +set global server_audit_timestamp_format='US=%f'; +set global server_audit_logging=on; +# %f must carry real microseconds, not a constant 000000 +set global server_audit_logging=off; +# A six-digit zero-padded microsecond field is logged +FOUND 1 /US=\d{6}.*usec_20/ in ts_ext_usec.log +# At least one entry carries a real (non-zero) microsecond value +usec_ok +######################################################################## # Cleanup: restore all settings ######################################################################## set global server_audit_timestamp_format='CMD-LINE-%Y-%m-%d'; diff --git a/mysql-test/suite/plugins/t/server_audit_timestamp.test b/mysql-test/suite/plugins/t/server_audit_timestamp.test index d8d195704b230..821a7180f3611 100644 --- a/mysql-test/suite/plugins/t/server_audit_timestamp.test +++ b/mysql-test/suite/plugins/t/server_audit_timestamp.test @@ -153,7 +153,7 @@ select 'fmt_iso'; set global server_audit_timestamp_format='T24=%T'; select 'fmt_t24'; ---echo # 2l: Microseconds %f (always 000000 until MDEV-39307 is fixed) +--echo # 2l: Microseconds %f render six zero-padded digits set global server_audit_timestamp_format='US=%f'; select 'fmt_usec'; @@ -197,7 +197,7 @@ set global server_audit_logging=off; --let SEARCH_PATTERN=T24=\d{2}:\d{2}:\d{2}.*fmt_t24 --source include/search_pattern_in_file.inc ---let SEARCH_PATTERN=US=000000.*fmt_usec +--let SEARCH_PATTERN=US=\d{6}.*fmt_usec --source include/search_pattern_in_file.inc --let SEARCH_PATTERN=TZ=[+-]\d{4}.*fmt_tz @@ -450,6 +450,49 @@ set global server_audit_logging=off; remove_file $SEARCH_FILE; +--echo ######################################################################## +--echo # Section 10: Microsecond resolution of %f (MDEV-39307) +--echo ######################################################################## + +let SEARCH_FILE= $MYSQLD_DATADIR/ts_ext_usec.log; +set global server_audit_file_path='ts_ext_usec.log'; +set global server_audit_events='query'; +set global server_audit_timestamp_format='US=%f'; +set global server_audit_logging=on; + +--echo # %f must carry real microseconds, not a constant 000000 +# Log several statements; the microsecond value at write time is +# effectively random, so at least one entry is expected to have a +# non-zero microsecond value. +--disable_query_log +--disable_result_log +let $i= 20; +while ($i) { + eval select 'usec_$i'; + dec $i; +} +--enable_result_log +--enable_query_log + +set global server_audit_logging=off; + +--echo # A six-digit zero-padded microsecond field is logged +--let SEARCH_PATTERN=US=\d{6}.*usec_20 +--source include/search_pattern_in_file.inc + +--echo # At least one entry carries a real (non-zero) microsecond value +perl; + my $ok= 0; + open(FILE, '<', $ENV{SEARCH_FILE}) or die "Can't open $ENV{SEARCH_FILE}: $!"; + while () { + if (/US=(\d{6})/ && $1 ne '000000') { $ok= 1; last; } + } + close(FILE); + print $ok ? "usec_ok\n" : "usec_bad\n"; +EOF + +remove_file $SEARCH_FILE; + --echo ######################################################################## --echo # Cleanup: restore all settings --echo ######################################################################## diff --git a/plugin/server_audit/server_audit.cc b/plugin/server_audit/server_audit.cc index 86146bc2e6874..87e44ff6ab998 100644 --- a/plugin/server_audit/server_audit.cc +++ b/plugin/server_audit/server_audit.cc @@ -74,6 +74,7 @@ static void closelog() {} #include #include +#include #include #include #include @@ -149,7 +150,6 @@ struct connection_info const char *query; int query_length; char query_buffer[1024]; - time_t query_time; int log_always; unsigned int port; char proxy[USERNAME_CHAR_LENGTH+1]; @@ -1103,7 +1103,7 @@ static void change_connection(struct connection_info *cn, Write to the log */ -static int write_log(const char *message, size_t len, time_t ts) +static int write_log(const char *message, size_t len, unsigned long long ts_us) { #if defined _WIN32 || !defined SUX_LOCK_GENERIC DBUG_ASSERT(lock_operations.is_locked_or_waiting()); @@ -1115,7 +1115,8 @@ static int write_log(const char *message, size_t len, time_t ts) if (logfile) { MYSQL_TIME ltime; - thd_gmt_sec_to_TIME(NULL, <ime, ts); + thd_gmt_sec_to_TIME(NULL, <ime, (time_t) (ts_us / 1000000)); + ltime.second_part= (ulong) (ts_us % 1000000); size_t ts_len= 0; char *ts_start= (char *) message - TIMESTAMP_OUTPUT_LENGTH; @@ -1162,10 +1163,10 @@ static int write_log(const char *message, size_t len, time_t ts) Write to the log, acquiring the lock. */ -static int write_log_and_lock(const char *message, size_t len, time_t ts) +static int write_log_and_lock(const char *message, size_t len, unsigned long long ts_us) { lock_operations.rd_lock(); - int result= write_log(message, len, ts); + int result= write_log(message, len, ts_us); lock_operations.rd_unlock(); return result; } @@ -1176,12 +1177,13 @@ static int write_log_and_lock(const char *message, size_t len, time_t ts) @param lock whether the caller did not acquire lock_operations */ -static int write_log_maybe_lock(const char *message, size_t len, bool lock, time_t ts) +static int write_log_maybe_lock(const char *message, size_t len, bool lock, + unsigned long long ts_us) { if (unlikely(!lock)) - return write_log(message, len, ts); + return write_log(message, len, ts_us); else - return write_log_and_lock(message, len, ts); + return write_log_and_lock(message, len, ts_us); } @@ -1237,14 +1239,11 @@ static size_t create_tls_obj(const struct mysql_event_connection *ev, char *obj_ static int log_proxy(const struct connection_info *cn, const struct mysql_event_connection *event) - { - time_t ctime; size_t csize; char raw_message[MAX_AUDIT_PAYLOAD_LENGTH + TIMESTAMP_OUTPUT_LENGTH]; char *message= raw_message + TIMESTAMP_OUTPUT_LENGTH; - (void) time(&ctime); csize= log_header(message, MAX_AUDIT_PAYLOAD_LENGTH - 1, servhost, servhost_len, cn->user, cn->user_length, @@ -1258,7 +1257,7 @@ static int log_proxy(const struct connection_info *cn, cn->proxy_host_length, cn->proxy_host, event->status); message[csize]= '\n'; - return write_log_and_lock(message, csize + 1, ctime); + return write_log_and_lock(message, csize + 1, my_hrtime().val); } @@ -1266,14 +1265,12 @@ static int log_connection(const struct connection_info *cn, const struct mysql_event_connection *event, const char *type) { - time_t ctime; size_t csize; char raw_message[MAX_AUDIT_PAYLOAD_LENGTH + TIMESTAMP_OUTPUT_LENGTH]; char *message= raw_message + TIMESTAMP_OUTPUT_LENGTH; char tls_obj[32]; size_t obj_len; - (void) time(&ctime); csize= log_header(message, MAX_AUDIT_PAYLOAD_LENGTH - 1, servhost, servhost_len, cn->user, cn->user_length, @@ -1286,21 +1283,19 @@ static int log_connection(const struct connection_info *cn, ",%.*s,%.*s,%d", cn->db_length, cn->db, (int) obj_len, tls_obj, event->status); message[csize]= '\n'; - return write_log_and_lock(message, csize + 1, ctime); + return write_log_and_lock(message, csize + 1, my_hrtime().val); } static int log_connection_event(const struct mysql_event_connection *event, const char *type) { - time_t ctime; size_t csize; char raw_message[MAX_AUDIT_PAYLOAD_LENGTH + TIMESTAMP_OUTPUT_LENGTH]; char *message= raw_message + TIMESTAMP_OUTPUT_LENGTH; char tls_obj[32]; size_t obj_len; - (void) time(&ctime); csize= log_header(message, MAX_AUDIT_PAYLOAD_LENGTH - 1, servhost, servhost_len, event->user, event->user_length, @@ -1312,7 +1307,7 @@ static int log_connection_event(const struct mysql_event_connection *event, ",%.*s,%.*s,%d", (int) event->database.length,event->database.str, (int) obj_len, tls_obj, event->status); message[csize]= '\n'; - return write_log_and_lock(message, csize + 1, ctime); + return write_log_and_lock(message, csize + 1, my_hrtime().val); } @@ -1509,9 +1504,10 @@ static int do_log_user(const char *name, int len, static int log_statement_ex(struct connection_info *cn, - time_t ev_time, unsigned long thd_id, int sql_cmd, - const char *query, unsigned int query_len, - int error_code, const char *type, int take_lock) + unsigned long long ev_time_us, unsigned long thd_id, + int sql_cmd, const char *query, + unsigned int query_len, int error_code, + const char *type, int take_lock) { size_t csize; char raw_message_loc[MAX_AUDIT_QUERY_LENGTH + TIMESTAMP_OUTPUT_LENGTH]; @@ -1620,7 +1616,7 @@ static int log_statement_ex(struct connection_info *cn, csize+= my_snprintf(message+csize, message_size - 1 - csize, "\',%d", error_code); message[csize]= '\n'; - result= write_log_maybe_lock(message, csize + 1, take_lock, ev_time); + result= write_log_maybe_lock(message, csize + 1, take_lock, ev_time_us); if (cn->sync_statement && output_type == OUTPUT_FILE && logfile) { @@ -1649,7 +1645,8 @@ static int log_statement(struct connection_info *cn, cn->query == (const char *)0x4f4f4f4f4f4f4f4fL ? NULL : cn->query, event->query_id, event->general_query_length, event->general_query, type)); - return log_statement_ex(cn, event->general_time, event->general_thread_id, + return log_statement_ex(cn, event->general_time_microseconds, + event->general_thread_id, sql_command, event->general_query, event->general_query_length, event->general_error_code, type, 1); @@ -1662,9 +1659,7 @@ static int log_table(const struct connection_info *cn, size_t csize; char raw_message[MAX_AUDIT_PAYLOAD_LENGTH + TIMESTAMP_OUTPUT_LENGTH]; char *message = raw_message + TIMESTAMP_OUTPUT_LENGTH; - time_t ctime; - (void) time(&ctime); csize= log_header(message, MAX_AUDIT_PAYLOAD_LENGTH - 1, servhost, servhost_len, event->user, SAFE_STRLEN_UI(event->user), @@ -1675,7 +1670,7 @@ static int log_table(const struct connection_info *cn, (int) event->database.length, event->database.str, (int) event->table.length, event->table.str); message[csize]= '\n'; - return write_log_and_lock(message, csize + 1, ctime); + return write_log_and_lock(message, csize + 1, my_hrtime().val); } @@ -1685,9 +1680,7 @@ static int log_rename(const struct connection_info *cn, size_t csize; char raw_message[MAX_AUDIT_PAYLOAD_LENGTH + TIMESTAMP_OUTPUT_LENGTH]; char *message= raw_message + TIMESTAMP_OUTPUT_LENGTH; - time_t ctime; - (void) time(&ctime); csize= log_header(message, MAX_AUDIT_PAYLOAD_LENGTH - 1, servhost, servhost_len, event->user, SAFE_STRLEN_UI(event->user), @@ -1702,7 +1695,7 @@ static int log_rename(const struct connection_info *cn, (int) event->new_database.length, event->new_database.str, (int) event->new_table.length, event->new_table.str); message[csize]= '\n'; - return write_log_and_lock(message, csize + 1, ctime); + return write_log_and_lock(message, csize + 1, my_hrtime().val); } @@ -1780,7 +1773,6 @@ static void update_connection_info(MYSQL_THD thd, struct connection_info *cn, cn->query_id= mode ? query_counter++ : event->query_id; cn->query= event->general_query; cn->query_length= event->general_query_length; - cn->query_time= (time_t) event->general_time; update_general_user(cn, event); } else if (init_db_command) @@ -1838,7 +1830,6 @@ static void update_connection_info(MYSQL_THD thd, struct connection_info *cn, get_str_n(cn->query_buffer, &cn->query_length, sizeof(cn->query_buffer), event->general_query, event->general_query_length); cn->query= cn->query_buffer; - cn->query_time= (time_t) event->general_time; break; default:; } @@ -2278,7 +2269,7 @@ static void log_current_query(MYSQL_THD thd) if (cn && !ci_needs_setup(cn) && cn->query_length) { cn->log_always= 1; - log_statement_ex(cn, cn->query_time, thd_get_thread_id(thd), + log_statement_ex(cn, my_hrtime().val, thd_get_thread_id(thd), thd_sql_command(thd), cn->query, cn->query_length, 0, "QUERY", 0); cn->log_always= 0; diff --git a/sql/log.cc b/sql/log.cc index 387795e30fce7..7f72c3dfc7cfb 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -1666,7 +1666,7 @@ bool LOGGER::general_log_write(THD *thd, enum enum_server_command command, user_host_len= make_user_name(thd, user_host_buff); current_time= my_hrtime(); - mysql_audit_general_log(thd, hrtime_to_time(current_time), + mysql_audit_general_log(thd, current_time, user_host_buff, user_host_len, command_name[(uint) command].str, (uint)command_name[(uint) command].length, diff --git a/sql/sql_audit.h b/sql/sql_audit.h index 3a03a7e3b9b76..b45f0fac060e9 100644 --- a/sql/sql_audit.h +++ b/sql/sql_audit.h @@ -112,7 +112,7 @@ void set_tls_version_of_event(THD *thd, mysql_event_connection *event) */ static inline -void mysql_audit_general_log(THD *thd, time_t time, +void mysql_audit_general_log(THD *thd, my_hrtime_t time, const char *user, uint userlen, const char *cmd, uint cmdlen, const char *query, uint querylen) @@ -123,7 +123,8 @@ void mysql_audit_general_log(THD *thd, time_t time, event.event_subclass= MYSQL_AUDIT_GENERAL_LOG; event.general_error_code= 0; - event.general_time= time; + event.general_time= hrtime_to_time(time); + event.general_time_microseconds= time.val; event.general_user= user; event.general_user_length= userlen; event.general_command= cmd; @@ -177,7 +178,19 @@ void mysql_audit_general(THD *thd, uint event_subtype, event.event_subclass= event_subtype; event.general_error_code= error_code; - event.general_time= my_time(0); + { + /* + Use the timestamp the server already maintains for the current + command (set once per query in dispatch_command), so that all audit + events of the same query carry the same time and no extra clock call + is made per event. Fall back to the current time if it is not set. + */ + my_hrtime_t general_time= { thd ? thd->start_utime : 0 }; + if (!general_time.val) + general_time= my_hrtime(); + event.general_time= hrtime_to_time(general_time); + event.general_time_microseconds= general_time.val; + } event.general_command= msg; event.general_command_length= safe_strlen_uint(msg); From c1e590a36b4c38599e84a8e70ce2990acbba096e Mon Sep 17 00:00:00 2001 From: Prathamesh Hukkeri Date: Fri, 14 Aug 2026 19:33:39 +0530 Subject: [PATCH 2/3] MDEV-39307: use wall-clock start_time for general audit events start_utime is derived from microsecond_interval_timer(), a monotonic interval timer, not a wall-clock timestamp. Using it for general_time/general_time_microseconds produced incorrect timestamps (often near 1970) for ERROR/RESULT/STATUS audit events. Use the per-command wall-clock timestamp (start_time + start_time_sec_part) and fall back to my_hrtime() only when unavailable. --- sql/sql_audit.h | 23 ++++++++++++++--------- 1 file changed, 14 insertions(+), 9 deletions(-) diff --git a/sql/sql_audit.h b/sql/sql_audit.h index b45f0fac060e9..59c59347af325 100644 --- a/sql/sql_audit.h +++ b/sql/sql_audit.h @@ -180,16 +180,21 @@ void mysql_audit_general(THD *thd, uint event_subtype, event.general_error_code= error_code; { /* - Use the timestamp the server already maintains for the current - command (set once per query in dispatch_command), so that all audit - events of the same query carry the same time and no extra clock call - is made per event. Fall back to the current time if it is not set. + Use the wall-clock timestamp the server already maintains for the + current command (set once per query in dispatch_command), so that + all audit events of the same query carry the same time and no extra + clock call is made per event. start_utime cannot be used here: it is + a monotonic interval timer, not a wall-clock timestamp. Fall back to + the current wall-clock time if the timestamp is not set. */ - my_hrtime_t general_time= { thd ? thd->start_utime : 0 }; - if (!general_time.val) - general_time= my_hrtime(); - event.general_time= hrtime_to_time(general_time); - event.general_time_microseconds= general_time.val; + unsigned long long general_time_us; + if (thd && thd->start_time) + general_time_us= (unsigned long long) thd->start_time * 1000000 + + thd->start_time_sec_part; + else + general_time_us= my_hrtime().val; + event.general_time= hrtime_to_time({ general_time_us }); + event.general_time_microseconds= general_time_us; } event.general_command= msg; event.general_command_length= safe_strlen_uint(msg); From 3c1d41c158dc2fe044c57fc313cbd367780aee1c Mon Sep 17 00:00:00 2001 From: Prathamesh Hukkeri Date: Fri, 14 Aug 2026 20:28:41 +0530 Subject: [PATCH 3/3] MDEV-39307: fix hrtime_to_time brace-init compile error hrtime_to_time is a macro that expects a my_hrtime_t with a .val member; passing a brace-initializer directly made the macro evaluate ({...}).val and fail to compile. Construct the my_hrtime_t explicitly instead. --- sql/sql_audit.h | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/sql/sql_audit.h b/sql/sql_audit.h index 59c59347af325..7e0fe4b6faab2 100644 --- a/sql/sql_audit.h +++ b/sql/sql_audit.h @@ -193,7 +193,8 @@ void mysql_audit_general(THD *thd, uint event_subtype, thd->start_time_sec_part; else general_time_us= my_hrtime().val; - event.general_time= hrtime_to_time({ general_time_us }); + my_hrtime_t general_time= { general_time_us }; + event.general_time= hrtime_to_time(general_time); event.general_time_microseconds= general_time_us; } event.general_command= msg;