Skip to content

MDEV-39307: Fix %f in audit plugin timestamp rendering zero microseconds #5547

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
prathamesh04 wants to merge 3 commits into
base: main
Choose a base branch
from
Open

MDEV-39307: Fix %f in audit plugin timestamp rendering zero microseconds #5547

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
31abeff
MDEV-39307: Fix %f in audit plugin timestamp rendering zero microseconds
prathamesh04 Aug 13, 2026
c1e590a
MDEV-39307: use wall-clock start_time for general audit events
prathamesh04 Aug 14, 2026
3c1d41c
MDEV-39307: fix hrtime_to_time brace-init compile error
prathamesh04 Aug 14, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 9 additions & 1 deletion include/mysql/plugin_audit.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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


/*************************************************************************
Expand Down Expand Up @@ -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;
};


Expand Down
1 change: 1 addition & 0 deletions include/mysql/plugin_audit.h.pp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
{
Expand Down
17 changes: 15 additions & 2 deletions mysql-test/suite/plugins/r/server_audit_timestamp.result
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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';
Expand Down
47 changes: 45 additions & 2 deletions mysql-test/suite/plugins/t/server_audit_timestamp.test
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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';

Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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 (<FILE>) {
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 ########################################################################
Expand Down
55 changes: 23 additions & 32 deletions plugin/server_audit/server_audit.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -74,6 +74,7 @@ static void closelog() {}

#include <my_global.h>
#include <my_base.h>
#include <my_sys.h>
#include <typelib.h>
#include <mysql/plugin.h>
#include <mysql/plugin_audit.h>
Expand Down Expand Up @@ -149,7 +150,6 @@ struct connection_info
const char *query;
int query_length;
char query_buffer[1024];
time_t query_time;

@gkodinov gkodinov Aug 13, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I disagree with the idea of the fix.

The server is not doing the right thing. In LOGGER::general_log_write() there's the following fragment:

my_hrtime_t current_time;
current_time= my_hrtime();
mysql_audit_general_log(thd, hrtime_to_time(current_time), ...)

That is, the server is fetching the time with the correct resolution, but, since the audit API only takes time_t, it's being downcast to time_t and the precision is lost.

Fetching the precise time is:

  • expensive
  • to be done only once per query since it's not very useful to have different timestamps for different actions in the same query.

I believe we should either extend the plugin API to take the hrtime or, similarly to MySQL, have a plugin service callback so that the plugin can fetch the hrtime.

int log_always;
unsigned int port;
char proxy[USERNAME_CHAR_LENGTH+1];
Expand Down Expand Up @@ -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());
Expand All @@ -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, &ltime, ts);
thd_gmt_sec_to_TIME(NULL, &ltime, (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;
Expand Down Expand Up @@ -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;
}
Expand All @@ -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);
}


Expand Down Expand Up @@ -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,
Expand All @@ -1258,22 +1257,20 @@ 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);
}


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,
Expand All @@ -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,
Expand All @@ -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);
}


Expand Down Expand Up @@ -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];
Expand Down Expand Up @@ -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)
{
Expand Down Expand Up @@ -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);
Expand All @@ -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),
Expand All @@ -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);
}


Expand All @@ -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),
Expand All @@ -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);
}


Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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:;
}
Expand Down Expand Up @@ -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;
Expand Down
2 changes: 1 addition & 1 deletion sql/log.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down
Loading
Loading