MDEV-39307: Fix %f in audit plugin timestamp rendering zero microseconds by prathamesh04 · Pull Request #5547 · MariaDB/server

prathamesh04 · 2026-08-13T11:41:05Z

Problem

The audit plugin built its log timestamp from a time_t value with second
resolution only (event.general_time), so the %f specifier in
server_audit_timestamp_format always rendered 000000. The server already
fetched a precise my_hrtime() once per query in
LOGGER::general_log_write(), but downcast it to seconds before passing it
to audit plugins.

Fix

Per review feedback, the server now forwards its high-resolution time
through the audit API instead of the plugin re-fetching it at write time:

mysql_event_general gains general_time_microseconds (in microseconds
since the epoch), appended at the end of the struct; general_time keeps
second resolution for backward compatibility. Interface version bumped to
MYSQL_AUDIT_INTERFACE_VERSION 0x0304.
mysql_audit_general_log() now takes my_hrtime_t and forwards the full
value (sql/log.cc no longer downcasts via hrtime_to_time).
The error/result/status events in mysql_audit_general() fill the new
field from a single my_hrtime() call.
The server_audit plugin uses event->general_time_microseconds for
query log entries. Connection and table events carry no timestamp in the
audit API, so the plugin takes the time at event time for those entries
(one fetch per event).

This addresses the review comment: the timestamp is fetched once by the
server per event, and the plugin no longer calls my_hrtime() at write
time.

Tests

mysql-test/suite/plugins/server_audit_timestamp:

section 2l now expects six zero-padded digits for %f
new section 10 logs 20 statements and verifies a real (non-zero)
microsecond value is written

Verified locally: mtr --suite=plugins server_audit_timestamp plus the
full server_audit* suite passes, and the audit log shows varying
microsecond values (e.g. US=721344).

prathamesh04 · 2026-08-13T11:41:24Z

@vuvova @sanja-byelkin — this fixes MDEV-39307 (audit plugin %f always renders 000000). Added an MTR testcase to server_audit_timestamp as the reporter requested. MCA signed.

gkodinov

Thank you for your contribution! This is a preliminary review.

From a preliminary technical PoV the contributions is correct. So I'm going to let it go to final review.

However, I feel strongly that the fix should be dome somewhat otherwise. See below on how I think it should be done.

Anyway, clarify this with the final reviewer please.

In case you agree with him to stay on the current course, then it's a bug fix and as such needs to go to the lowest affected version instead of the main branch.

gkodinov · 2026-08-13T12:11:24Z

  const char *query;
  int query_length;
  char query_buffer[1024];
-  time_t query_time;


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.

Copilot

Pull request overview

This PR fixes %f microseconds rendering in the server_audit plugin timestamp by switching log timestamp generation from second-resolution time_t values to microsecond-resolution my_hrtime() and propagating the microsecond component via MYSQL_TIME::second_part.

Changes:

Update write_log() to derive timestamp seconds from hrtime_to_time(my_hrtime()) and microseconds from hrtime_sec_part(), so %f outputs real microseconds.
Remove now-unused second-resolution timestamp plumbing (time_t parameters/fields and time() callsites) from the audit log call chain.
Extend the server_audit_timestamp MTR test to expect 6 digits for %f and add a new section verifying at least one non-zero microsecond value is logged.

Reviewed changes

Copilot reviewed 3 out of 3 changed files in this pull request and generated no comments.

File	Description
plugin/server_audit/server_audit.cc	Switch audit log timestamping to `my_hrtime()` and set `MYSQL_TIME::second_part` for `%f`; remove unused `time_t` plumbing.
mysql-test/suite/plugins/t/server_audit_timestamp.test	Update `%f` expectations and add a new test section that asserts non-zero microseconds appear.
mysql-test/suite/plugins/r/server_audit_timestamp.result	Update expected output to match the new `%f` behavior and new test section output.

💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

gkodinov · 2026-08-13T12:32:42Z

FYI: According to our development cycle we work on bugs In the following periods 15 Mar-30 Apr, 15 Jun-30 Jul, 15 Sep-30 Oct and 15 Dec-31 Jan. So, please, expect to get a review somewhere between these two dates and the goal is to have your PR merged before the second date

prathamesh04 · 2026-08-13T12:38:30Z

@gkodinov thank you for the review. I reworked the fix as you suggested: the server now forwards its high-resolution time through the audit API instead of the plugin re-fetching my_hrtime() at write time.

mysql_audit_general_log() now takes my_hrtime_t (sql/log.cc:1669 passes current_time directly, no more hrtime_to_time downcast).
mysql_event_general gained general_time_microseconds (appended at the end of the struct, general_time keeps second resolution for backward compatibility), MYSQL_AUDIT_INTERFACE_VERSION bumped to 0x0304.
The error/result/status events in mysql_audit_general() fill it from a single my_hrtime() call.
server_audit now uses event->general_time_microseconds for query entries; connection/table events have no server timestamp in the audit API, so the plugin takes the time once per event for those.

Since this is now an API extension rather than a bug fix to existing code, main remains the target branch.

Could the final reviewer please confirm this approach?

prathamesh04 · 2026-08-13T16:21:18Z

Note on the remaining red buildbot: the only failing builder is amd64-ubuntu-2204-debug-ps, and its failure is unrelated to this change.

The failing test is rpl.rpl_row_foreign_key_mdl, a replication test that is a known sporadic failure on the buildbot (sync_with_master timeout), tracked in MDEV-39023. It does not exercise the audit plugin or any code touched here.
main.cte_update_delete and perfschema.bad_option only trigger the informational --check-testcases notice (a server variable changed during the test), not a result mismatch; both pass locally.

The ABI failure that affected the other builders was fixed by regenerating the include/mysql/plugin_audit.h.pp canon; all 15 other buildbots now pass.

grooverdan · 2026-08-14T00:06:58Z

    event.general_error_code= error_code;
-    event.general_time= my_time(0);
+    {
+      my_hrtime_t general_time= my_hrtime();


Wondering if we can use one of the thd time values like start_utime (set by dispatch_command?

Thanks for re-implementation..

Hi @grooverdan, interesting. mysql_audit_general() now uses thd->start_utime (the per-command timestamp set in dispatch_command) for the error/result/status events instead of calling my_hrtime(), so no extra clock call is made and all audit events of a query carry the same time. It falls back to my_hrtime() only when the THD is absent (mysql_audit_general(0, ...) at startup) or the timestamp is not set. The LOG path already takes the server's once-per-query my_hrtime() in LOGGER::general_log_write() and forwards it unchanged. Rebuilt and re-ran the full server_audit* MTR suite — all green.

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.

Copilot

Pull request overview

Copilot reviewed 7 out of 7 changed files in this pull request and generated 1 comment.

Suppressed comments (1)

plugin/server_audit/server_audit.cc:1119

thd_gmt_sec_to_TIME() takes a my_time_t (server-defined time type). Casting to time_t here can unnecessarily narrow/truncate the seconds value on platforms where time_t differs, and it’s inconsistent with the function signature. Cast to my_time_t instead (and keep constants as ULL to avoid implicit narrowing).

      MYSQL_TIME ltime;
      thd_gmt_sec_to_TIME(NULL, &ltime, (time_t) (ts_us / 1000000));
      ltime.second_part= (ulong) (ts_us % 1000000);

vuvova · 2026-08-14T13:44:49Z

+      /*
+        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;
+    }


that's right, one cannot use interval timer for wall-clock time

Good catch, fixed. I replaced thd->start_utime with the per-command wall-clock timestamp (thd->start_time + thd->start_time_sec_part, as set by set_start_time() in dispatch_command), falling back to my_hrtime() only when the timestamp is not set. So the error/result/status events now carry a real wall-clock microsecond timestamp instead of an interval-timer value near 1970. Updated in c1e590a.

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.

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.

gkodinov added the External Contribution All PRs from entities outside of MariaDB Foundation, Corporation, Codership agreements. label Aug 13, 2026

gkodinov approved these changes Aug 13, 2026

View reviewed changes

gkodinov requested a review from sanja-byelkin August 13, 2026 12:16

gkodinov assigned sanja-byelkin Aug 13, 2026

vuvova requested a lite review from Copilot August 13, 2026 12:20

Copilot started reviewing on behalf of vuvova August 13, 2026 12:21 View session

Copilot AI reviewed Aug 13, 2026

View reviewed changes

prathamesh04 force-pushed the mdev-39307-audit-timestamp-microseconds branch from a39d0db to ee166c6 Compare August 13, 2026 12:38

prathamesh04 force-pushed the mdev-39307-audit-timestamp-microseconds branch from ee166c6 to 7250b72 Compare August 13, 2026 15:13

grooverdan reviewed Aug 14, 2026

View reviewed changes

prathamesh04 force-pushed the mdev-39307-audit-timestamp-microseconds branch from 7250b72 to 31abeff Compare August 14, 2026 04:55

vuvova requested a lite review from Copilot August 14, 2026 13:25

Copilot started reviewing on behalf of vuvova August 14, 2026 13:25 View session

Copilot AI reviewed Aug 14, 2026

View reviewed changes

prathamesh04 added 2 commits August 14, 2026 19:33

MDEV-39307: fix hrtime_to_time brace-init compile error

3c1d41c

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.

Navigation Menu

Uh oh!

Uh oh!

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

MDEV-39307: Fix %f in audit plugin timestamp rendering zero microseconds#5547
prathamesh04 wants to merge 3 commits into
MariaDB:mainfrom
prathamesh04:mdev-39307-audit-timestamp-microseconds

prathamesh04 commented Aug 13, 2026 •

edited

Loading

Uh oh!

prathamesh04 commented Aug 13, 2026 •

edited

Loading

Uh oh!

gkodinov left a comment

Uh oh!

gkodinov Aug 13, 2026

Uh oh!

Copilot AI left a comment

Uh oh!

gkodinov commented Aug 13, 2026

Uh oh!

prathamesh04 commented Aug 13, 2026

Uh oh!

prathamesh04 commented Aug 13, 2026

Uh oh!

grooverdan Aug 14, 2026

Uh oh!

prathamesh04 Aug 14, 2026 •

edited

Loading

Uh oh!

Copilot AI left a comment

Uh oh!

vuvova Aug 14, 2026

Uh oh!

prathamesh04 Aug 14, 2026

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

6 participants

Uh oh!

Uh oh!

Conversation

prathamesh04 commented Aug 13, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Problem

Fix

Tests

Uh oh!

prathamesh04 commented Aug 13, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

gkodinov left a comment

Choose a reason for hiding this comment

Uh oh!

gkodinov Aug 13, 2026

Choose a reason for hiding this comment

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Reviewed changes

Uh oh!

gkodinov commented Aug 13, 2026

Uh oh!

prathamesh04 commented Aug 13, 2026

Uh oh!

prathamesh04 commented Aug 13, 2026

Uh oh!

grooverdan Aug 14, 2026

Choose a reason for hiding this comment

Uh oh!

prathamesh04 Aug 14, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull request overview

Uh oh!

vuvova Aug 14, 2026

Choose a reason for hiding this comment

Uh oh!

prathamesh04 Aug 14, 2026

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Milestone

Development

Uh oh!

6 participants

prathamesh04 commented Aug 13, 2026 •

edited

Loading

prathamesh04 commented Aug 13, 2026 •

edited

Loading

prathamesh04 Aug 14, 2026 •

edited

Loading