From ec7070e76db882b09f679786fa06d311e998b899 Mon Sep 17 00:00:00 2001 From: Przemyslaw Skibinski Date: Tue, 2 Dec 2025 17:49:23 +0100 Subject: [PATCH] PS-10347 [8.0]: Ensure strict JSON compliance and robust field separation in audit_log_read()/AuditJsonHandler Refactors the JSON serialization logic within AuditJsonHandler to guarantee strict compliance with the JSON standard by eliminating trailing commas and centralizing field separation control. The previous approach of appending ", " after every value handler was inconsistent and required error-prone comma removal logic in EndObject. This change adopts a safer, state-driven approach: - Centralized Comma Management: The responsibility for adding the comma separator is moved entirely from the value handlers (Int, String, etc.) to the Key() handler. - State-Driven Separation: The new m_is_first_field state flag, set in StartObject() and checked/updated in Key(), ensures a comma is prepended only when necessary (i.e., not for the first field), thereby naturally preventing trailing commas within objects. - Inter-Event Separation: Confirmed that the ,\n separator is correctly appended to separate top-level audit event objects in the array. --- .../json_reader/audit_json_handler.cc | 69 +++-- .../json_reader/audit_json_handler.h | 1 + .../udf_audit_log_read_validate_output.result | 254 ++++++++++++++++++ ..._audit_log_read_validate_output-master.opt | 1 + .../t/udf_audit_log_read_validate_output.test | 64 +++++ 5 files changed, 366 insertions(+), 23 deletions(-) create mode 100644 plugin/audit_log_filter/tests/mtr/r/udf_audit_log_read_validate_output.result create mode 100644 plugin/audit_log_filter/tests/mtr/t/udf_audit_log_read_validate_output-master.opt create mode 100644 plugin/audit_log_filter/tests/mtr/t/udf_audit_log_read_validate_output.test diff --git a/plugin/audit_log_filter/json_reader/audit_json_handler.cc b/plugin/audit_log_filter/json_reader/audit_json_handler.cc index 6d3317cfc131..de0b6673285a 100644 --- a/plugin/audit_log_filter/json_reader/audit_json_handler.cc +++ b/plugin/audit_log_filter/json_reader/audit_json_handler.cc @@ -14,6 +14,7 @@ Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA */ #include "plugin/audit_log_filter/json_reader/audit_json_handler.h" +#include // std::strcpy #include "plugin/audit_log_filter/audit_log_reader.h" namespace audit_log_filter::json_reader { @@ -40,7 +41,8 @@ AuditJsonHandler::AuditJsonHandler( m_out_buff_size{out_buff_size}, m_used_buff_size{0}, m_printed_events_count{0}, - m_reading_start_reached{false} {} + m_reading_start_reached{false}, + m_is_first_field{false} {} char *AuditJsonHandler::get_result_buffer_ptr() noexcept { return m_out_buff.get(); @@ -62,7 +64,10 @@ void AuditJsonHandler::iterative_parse_init() noexcept { } void AuditJsonHandler::iterative_parse_close(bool with_null_tag) noexcept { - if (m_used_buff_size > 2 && !with_null_tag) { + // Remove the trailing ",\n" from the last event, if present, + // to ensure valid JSON array closing. + if (m_used_buff_size >= 2 && (m_current_buff - 2)[0] == ',' && + (m_current_buff - 1)[0] == '\n' && !with_null_tag) { m_current_buff -= 2; m_used_buff_size -= 2; } @@ -72,60 +77,74 @@ void AuditJsonHandler::iterative_parse_close(bool with_null_tag) noexcept { write_out_buff(closing_tag.c_str(), closing_tag.length()); } +// --- Value Handlers --- + bool AuditJsonHandler::Null() { return true; } bool AuditJsonHandler::Bool(bool value) { - m_event_str << (value ? "true" : "false") << ", "; + m_event_str << (value ? "true" : "false"); return true; } bool AuditJsonHandler::Int(int value) { - update_bookmark(value); - m_event_str << value << ", "; + update_bookmark(static_cast(value)); + m_event_str << value; return true; } bool AuditJsonHandler::Uint(unsigned value) { - update_bookmark(value); - m_event_str << value << ", "; + update_bookmark(static_cast(value)); + m_event_str << value; return true; } bool AuditJsonHandler::Int64(int64_t value) { - update_bookmark(value); - m_event_str << value << ", "; + update_bookmark(static_cast(value)); + m_event_str << value; return true; } bool AuditJsonHandler::Uint64(uint64_t value) { update_bookmark(value); - m_event_str << value << ", "; + m_event_str << value; return true; } bool AuditJsonHandler::Double(double value) { - m_event_str << value << ", "; + m_event_str << value; return true; } -bool AuditJsonHandler::String(const char *value, - rapidjson::SizeType length [[maybe_unused]], +bool AuditJsonHandler::String(const char *value, rapidjson::SizeType length, bool copy [[maybe_unused]]) { - update_bookmark(value); - m_event_str << "\"" << value << "\", "; + std::string s_value(value, length); + update_bookmark(s_value); + m_event_str << "\"" << s_value << "\""; return true; } +// --- Structure Handlers --- + bool AuditJsonHandler::StartObject() { ++m_obj_level; m_event_str << "{"; + // Reset flag: the first key encountered will not have a comma separator + m_is_first_field = true; return true; } -bool AuditJsonHandler::Key(const char *str, - rapidjson::SizeType length [[maybe_unused]], +bool AuditJsonHandler::Key(const char *str, rapidjson::SizeType length, bool copy [[maybe_unused]]) { - m_current_key_name = str; + m_current_key_name.assign(str, length); + + // Manage comma separation and state before appending the key. + if (m_is_first_field) { + m_is_first_field = false; // This is the first field, so unset the flag + } else { + m_event_str << ", "; // Prepend separator if a previous field exists + } + + // Append key and colon m_event_str << "\"" << str << "\": "; return true; } @@ -136,20 +155,24 @@ bool AuditJsonHandler::EndObject(rapidjson::SizeType memberCount --m_obj_level; } - if (m_obj_level > 0) { - // remove comma after last event - m_event_str.seekp(-2, std::ios_base::end); - } - + // Append the closing brace. m_event_str << "}"; + // If closing an inner object (m_obj_level is now > 0), or the top-level + // object, ensure the m_is_first_field is false, so the next Key() call + // (if any, in the parent) correctly prepends a comma. + m_is_first_field = false; + + // Handle the completed top-level event object. if (m_obj_level == 0) { if (!check_reading_start_reached()) { clear_current_event(); return true; } + // Add the inter-event separator (comma and newline). m_event_str << ",\n"; + const auto event_length = m_event_str.str().length(); const auto max_array_length = m_reader_context->batch_reader_args->max_array_length; diff --git a/plugin/audit_log_filter/json_reader/audit_json_handler.h b/plugin/audit_log_filter/json_reader/audit_json_handler.h index 3eaeae0574a4..17f99464a6bf 100644 --- a/plugin/audit_log_filter/json_reader/audit_json_handler.h +++ b/plugin/audit_log_filter/json_reader/audit_json_handler.h @@ -90,6 +90,7 @@ class AuditJsonHandler ulong m_used_buff_size; ulong m_printed_events_count; bool m_reading_start_reached; + bool m_is_first_field; LogBookmark m_current_event_bookmark; }; diff --git a/plugin/audit_log_filter/tests/mtr/r/udf_audit_log_read_validate_output.result b/plugin/audit_log_filter/tests/mtr/r/udf_audit_log_read_validate_output.result new file mode 100644 index 000000000000..3605bd21790d --- /dev/null +++ b/plugin/audit_log_filter/tests/mtr/r/udf_audit_log_read_validate_output.result @@ -0,0 +1,254 @@ +# +# PS-10347: AuditJsonHandler used by audit_log_read UDF returns malformed JSON +# https://perconadev.atlassian.net/browse/PS-10347 +# +CREATE TABLE t1 (c1 INT); +SELECT audit_log_filter_set_filter('log_all', '{ "filter": { "log": true } }'); +audit_log_filter_set_filter('log_all', '{ "filter": { "log": true } }') +OK +SET @start_bookmark := audit_log_read_bookmark(); +Turn on audit log +SELECT audit_log_filter_set_user('%', 'log_all'); +audit_log_filter_set_user('%', 'log_all') +OK +INSERT INTO t1 VALUES (1); +Turn off audit log +SELECT audit_log_filter_remove_filter('log_all'); +audit_log_filter_remove_filter('log_all') +OK +Rotate to close a log file and get access to it +Print audit log filter output +[ + { + "timestamp": "", + "id": 0, + "class": "audit", + "server_id": 1 + }, + { + "timestamp": "", + "id": 1, + "class": "query", + "event": "query_status_end", + "connection_id": , + "query_data": { + "query": "SELECT audit_log_filter_set_user('%', 'log_all')", + "status": 0, + "sql_command": "select"} + }, + { + "timestamp": "", + "id": 2, + "class": "general", + "event": "result", + "connection_id": , + "account": { "user": "root[root] @ localhost []", "host": "localhost" }, + "login": { "user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": "" }, + "general_data": { + "command": "", + "sql_command": "select", + "query": "SELECT audit_log_filter_set_user('%', 'log_all')", + "status": 0} + }, + { + "timestamp": "", + "id": 3, + "class": "general", + "event": "status", + "connection_id": , + "account": { "user": "root[root] @ localhost []", "host": "localhost" }, + "login": { "user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": "" }, + "general_data": { + "command": "Query", + "sql_command": "select", + "query": "SELECT audit_log_filter_set_user('%', 'log_all')", + "status": 0} + }, + { + "timestamp": "", + "id": 4, + "class": "command", + "event": "command_end", + "connection_id": , + "command_data": { + "name": "command_end", + "status": 0, + "command": "query"} + }, + { + "timestamp": "", + "id": 5, + "class": "command", + "event": "command_start", + "connection_id": , + "command_data": { + "name": "command_start", + "status": 0, + "command": "query"} + }, + { + "timestamp": "", + "id": 6, + "class": "general", + "event": "log", + "connection_id": , + "account": { "user": "root[root] @ localhost []", "host": "localhost" }, + "login": { "user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": "" }, + "general_data": { + "command": "Query", + "sql_command": "insert", + "query": "INSERT INTO t1 VALUES (1)", + "status": 0} + }, + { + "timestamp": "", + "id": 7, + "class": "query", + "event": "query_start", + "connection_id": , + "query_data": { + "query": "INSERT INTO t1 VALUES (1)", + "status": 0, + "sql_command": "insert"} + }, + { + "timestamp": "", + "id": 8, + "class": "table_access", + "event": "insert", + "connection_id": , + "table_access_data": { + "db": "test", + "table": "t1", + "query": "INSERT INTO t1 VALUES (1)", + "sql_command": "insert"} + }, + { + "timestamp": "", + "id": 9, + "class": "query", + "event": "query_status_end", + "connection_id": , + "query_data": { + "query": "INSERT INTO t1 VALUES (1)", + "status": 0, + "sql_command": "insert"} + }, + { + "timestamp": "", + "id": 10, + "class": "general", + "event": "result", + "connection_id": , + "account": { "user": "root[root] @ localhost []", "host": "localhost" }, + "login": { "user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": "" }, + "general_data": { + "command": "", + "sql_command": "insert", + "query": "INSERT INTO t1 VALUES (1)", + "status": 0} + }, + { + "timestamp": "", + "id": 11, + "class": "general", + "event": "status", + "connection_id": , + "account": { "user": "root[root] @ localhost []", "host": "localhost" }, + "login": { "user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": "" }, + "general_data": { + "command": "Query", + "sql_command": "insert", + "query": "INSERT INTO t1 VALUES (1)", + "status": 0} + }, + { + "timestamp": "", + "id": 12, + "class": "command", + "event": "command_end", + "connection_id": , + "command_data": { + "name": "command_end", + "status": 0, + "command": "query"} + }, + { + "timestamp": "", + "id": 13, + "class": "command", + "event": "command_start", + "connection_id": , + "command_data": { + "name": "command_start", + "status": 0, + "command": "query"} + }, + { + "timestamp": "", + "id": 14, + "class": "general", + "event": "log", + "connection_id": , + "account": { "user": "root[root] @ localhost []", "host": "localhost" }, + "login": { "user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": "" }, + "general_data": { + "command": "Query", + "sql_command": "select", + "query": "SELECT audit_log_filter_remove_filter('log_all')", + "status": 0} + }, + { + "timestamp": "", + "id": 15, + "class": "query", + "event": "query_start", + "connection_id": , + "query_data": { + "query": "SELECT audit_log_filter_remove_filter('log_all')", + "status": 0, + "sql_command": "select"} + } +] +Validate audit log filter output +File format Ok +Export output of audit_log_read('$start_bookmark_esc') to a file +SET @start_bookmark_esc := REPLACE(@start_bookmark, '"', '\\"'); +Validate output of audit_log_read('$start_bookmark_esc') +File format Ok +Start processing audit log from the beginning. Get 5 events from "audit_log_read" +SELECT audit_log_read(JSON_SET(@start_bookmark, '$.max_array_length', 5)); +audit_log_read(JSON_SET(@start_bookmark, '$.max_array_length', 5)) +[ +{"timestamp": "", "id": 0, "class": "audit", "server_id": 1}, +{"timestamp": "", "id": 1, "class": "query", "event": "query_status_end", "connection_id": , "query_data": {"query": "SELECT audit_log_filter_set_user('%', 'log_all')", "status": 0, "sql_command": "select"}}, +{"timestamp": "", "id": 2, "class": "general", "event": "result", "connection_id": , "account": {"user": "root[root] @ localhost []", "host": "localhost"}, "login": {"user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": ""}, "general_data": {"command": "", "sql_command": "select", "query": "SELECT audit_log_filter_set_user('%', 'log_all')", "status": 0}}, +{"timestamp": "", "id": 3, "class": "general", "event": "status", "connection_id": , "account": {"user": "root[root] @ localhost []", "host": "localhost"}, "login": {"user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": ""}, "general_data": {"command": "Query", "sql_command": "select", "query": "SELECT audit_log_filter_set_user('%', 'log_all')", "status": 0}}, +{"timestamp": "", "id": 4, "class": "command", "event": "command_end", "connection_id": , "command_data": {"name": "command_end", "status": 0, "command": "query"}} +] + +Get 8 events from "INSERT INTO t1 VALUES (1)" +TODO: We have a bug here that audit_log_read() returns all records instead of just 8 records +SELECT audit_log_read('{"max_array_length": 8}'); +audit_log_read('{"max_array_length": 8}') +[ +{"timestamp": "", "id": 5, "class": "command", "event": "command_start", "connection_id": , "command_data": {"name": "command_start", "status": 0, "command": "query"}}, +{"timestamp": "", "id": 6, "class": "general", "event": "log", "connection_id": , "account": {"user": "root[root] @ localhost []", "host": "localhost"}, "login": {"user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": ""}, "general_data": {"command": "Query", "sql_command": "insert", "query": "INSERT INTO t1 VALUES (1)", "status": 0}}, +{"timestamp": "", "id": 7, "class": "query", "event": "query_start", "connection_id": , "query_data": {"query": "INSERT INTO t1 VALUES (1)", "status": 0, "sql_command": "insert"}}, +{"timestamp": "", "id": 8, "class": "table_access", "event": "insert", "connection_id": , "table_access_data": {"db": "test", "table": "t1", "query": "INSERT INTO t1 VALUES (1)", "sql_command": "insert"}}, +{"timestamp": "", "id": 9, "class": "query", "event": "query_status_end", "connection_id": , "query_data": {"query": "INSERT INTO t1 VALUES (1)", "status": 0, "sql_command": "insert"}}, +{"timestamp": "", "id": 10, "class": "general", "event": "result", "connection_id": , "account": {"user": "root[root] @ localhost []", "host": "localhost"}, "login": {"user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": ""}, "general_data": {"command": "", "sql_command": "insert", "query": "INSERT INTO t1 VALUES (1)", "status": 0}}, +{"timestamp": "", "id": 11, "class": "general", "event": "status", "connection_id": , "account": {"user": "root[root] @ localhost []", "host": "localhost"}, "login": {"user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": ""}, "general_data": {"command": "Query", "sql_command": "insert", "query": "INSERT INTO t1 VALUES (1)", "status": 0}}, +{"timestamp": "", "id": 12, "class": "command", "event": "command_end", "connection_id": , "command_data": {"name": "command_end", "status": 0, "command": "query"}}, +{"timestamp": "", "id": 13, "class": "command", "event": "command_start", "connection_id": , "command_data": {"name": "command_start", "status": 0, "command": "query"}}, +{"timestamp": "", "id": 14, "class": "general", "event": "log", "connection_id": , "account": {"user": "root[root] @ localhost []", "host": "localhost"}, "login": {"user": "root[root] @ localhost []", "os": "", "ip": "", "proxy": ""}, "general_data": {"command": "Query", "sql_command": "select", "query": "SELECT audit_log_filter_remove_filter('log_all')", "status": 0}}, +{"timestamp": "", "id": 15, "class": "query", "event": "query_start", "connection_id": , "query_data": {"query": "SELECT audit_log_filter_remove_filter('log_all')", "status": 0, "sql_command": "select"}}, +null +] + +Get remaining events +SELECT audit_log_read('null'); +audit_log_read('null') +OK +# Cleanup +DROP TABLE t1; diff --git a/plugin/audit_log_filter/tests/mtr/t/udf_audit_log_read_validate_output-master.opt b/plugin/audit_log_filter/tests/mtr/t/udf_audit_log_read_validate_output-master.opt new file mode 100644 index 000000000000..5bd77533d141 --- /dev/null +++ b/plugin/audit_log_filter/tests/mtr/t/udf_audit_log_read_validate_output-master.opt @@ -0,0 +1 @@ +--audit_log_filter_format=JSON diff --git a/plugin/audit_log_filter/tests/mtr/t/udf_audit_log_read_validate_output.test b/plugin/audit_log_filter/tests/mtr/t/udf_audit_log_read_validate_output.test new file mode 100644 index 000000000000..0dcdf140197f --- /dev/null +++ b/plugin/audit_log_filter/tests/mtr/t/udf_audit_log_read_validate_output.test @@ -0,0 +1,64 @@ +--echo # +--echo # PS-10347: AuditJsonHandler used by audit_log_read UDF returns malformed JSON +--echo # https://perconadev.atlassian.net/browse/PS-10347 +--echo # + +--source audit_tables_init.inc + +--let $audit_filter_log_path = `SELECT @@global.datadir` + +CREATE TABLE t1 (c1 INT); +SELECT audit_log_filter_set_filter('log_all', '{ "filter": { "log": true } }'); +SET @start_bookmark := audit_log_read_bookmark(); + +--echo Turn on audit log +SELECT audit_log_filter_set_user('%', 'log_all'); + +INSERT INTO t1 VALUES (1); + +--echo Turn off audit log +SELECT audit_log_filter_remove_filter('log_all'); + +--echo Rotate to close a log file and get access to it +--let $audit_filter_rotate_name=`SELECT audit_log_rotate()` + +--echo Print audit log filter output +# --echo audit_filter_log_name=$audit_filter_log_path/$audit_filter_rotate_name +--replace_regex /"connection_id": \d*/"connection_id": / /"timestamp":\s*"[^"]*"/"timestamp": ""/ +--cat_file $audit_filter_log_path/$audit_filter_rotate_name + +--echo Validate audit log filter output +--let $audit_filter_log_check_one = $audit_filter_rotate_name +--let $audit_filter_log_format = json +--source validate_logs_format.inc + +--echo Export output of audit_log_read('\$start_bookmark_esc') to a file +SET @start_bookmark_esc := REPLACE(@start_bookmark, '"', '\\"'); +--let $start_bookmark_esc=`SELECT @start_bookmark_esc` +--let $out_file=audit_read.out +--exec $MYSQL --skip-column-names --raw -e "SELECT audit_log_read('$start_bookmark_esc');" > $audit_filter_log_path/$out_file +# --cat_file $audit_filter_log_path/$out_file + +--echo Validate output of audit_log_read('\$start_bookmark_esc') +--let $audit_filter_log_check_one = $out_file +--let $audit_filter_log_format = json +--source validate_logs_format.inc +--remove_file $audit_filter_log_path/$out_file + +--echo Start processing audit log from the beginning. Get 5 events from "audit_log_read" +--replace_regex /"connection_id": \d*/"connection_id": / /"timestamp":\s*"[^"]*"/"timestamp": ""/ +SELECT audit_log_read(JSON_SET(@start_bookmark, '$.max_array_length', 5)); + +--echo Get 8 events from "INSERT INTO t1 VALUES (1)" +--echo TODO: We have a bug here that audit_log_read() returns all records instead of just 8 records +--replace_regex /"connection_id": \d*/"connection_id": / /"timestamp":\s*"[^"]*"/"timestamp": ""/ +SELECT audit_log_read('{"max_array_length": 8}'); + +--echo Get remaining events +--replace_regex /"connection_id": \d*/"connection_id": / /"timestamp":\s*"[^"]*"/"timestamp": ""/ +SELECT audit_log_read('null'); + +--echo # Cleanup +--source audit_tables_cleanup.inc + +DROP TABLE t1;