From 88fdfb9d5ab7b9d7ea8c96e12fe1c5b475252bd2 Mon Sep 17 00:00:00 2001 From: Juliana Fajardini Date: Tue, 20 May 2025 12:59:10 -0300 Subject: [PATCH] pgsql: debug validation on duplicated request msgs There shouldn't be duplicated messages in the requests Vec. And thus the parser shouldn't log duplicated keys nor messages. Add debug validations to ensure this. With PGSQL's current state machine, most frontend/ client messages will lead to the creation of a new transaction - which would prevent duplicated messages being pushed to the requests array and reaching the logger. The current exceptions for that are: - CopyDataIn - CopyDone - CopyFail Thus, debug statements were added for those cases. CopyDone and CopyFail, per the documentation, shouldn't be seen duplicated on the wire for the same transaction. CopyDataIn -- yes, but we consolidate those, so the expectation is that they won't be duplicated in the requests array or when reaching the logger either. Related to Task #7645 --- rust/src/pgsql/logger.rs | 179 +++++++++++++++++++++------------------ 1 file changed, 96 insertions(+), 83 deletions(-) diff --git a/rust/src/pgsql/logger.rs b/rust/src/pgsql/logger.rs index f6053515bf..f39580e1b0 100644 --- a/rust/src/pgsql/logger.rs +++ b/rust/src/pgsql/logger.rs @@ -31,12 +31,10 @@ fn log_pgsql(tx: &PgsqlTransaction, flags: u32, js: &mut JsonBuilder) -> Result< js.set_uint("tx_id", tx.tx_id)?; if !tx.requests.is_empty() { // For now, even if 'requests' is an array, we don't need to log it as such, as - // there are no duplicated messages + // there should be no duplicated messages, and there should be no more than 2 requests per tx + debug_validate_bug_on!(tx.requests.len() > 2); js.open_object("request")?; - for request in &tx.requests { - SCLogNotice!("Suricata requests length: {}", tx.requests.len()); - log_request(request, flags, js)?; - } + log_request(tx, flags, js)?; js.close()?; } else if tx.responses.is_empty() { SCLogDebug!("Suricata created an empty PGSQL transaction"); @@ -55,86 +53,101 @@ fn log_pgsql(tx: &PgsqlTransaction, flags: u32, js: &mut JsonBuilder) -> Result< Ok(()) } -fn log_request(req: &PgsqlFEMessage, flags: u32, js: &mut JsonBuilder) -> Result<(), JsonError> { - match req { - PgsqlFEMessage::StartupMessage(StartupPacket { - length: _, - proto_major, - proto_minor, - params, - }) => { - let proto = format!("{}.{}", proto_major, proto_minor); - js.set_string("protocol_version", &proto)?; - js.set_object("startup_parameters", &log_startup_parameters(params)?)?; - } - PgsqlFEMessage::SSLRequest(_) => { - js.set_string("message", "SSL Request")?; - } - PgsqlFEMessage::SASLInitialResponse(SASLInitialResponsePacket { - identifier: _, - length: _, - auth_mechanism, - param_length: _, - sasl_param, - }) => { - js.set_string("sasl_authentication_mechanism", auth_mechanism.to_str())?; - js.set_string_from_bytes("sasl_param", sasl_param)?; - } - PgsqlFEMessage::PasswordMessage(RegularPacket { - identifier: _, - length: _, - payload, - }) => { - if flags & PGSQL_LOG_PASSWORDS != 0 { +fn log_request(tx: &PgsqlTransaction, flags: u32, js: &mut JsonBuilder) -> Result<(), JsonError> { + // CopyFail, ConsolidatedCopyDataIn, CopyDone + let mut duplicated_messages: [u8; 3] = [0, 0, 0]; + for req in &tx.requests { + SCLogDebug!("Suricata requests length: {}", tx.requests.len()); + match req { + PgsqlFEMessage::StartupMessage(StartupPacket { + length: _, + proto_major, + proto_minor, + params, + }) => { + let proto = format!("{}.{}", proto_major, proto_minor); + js.set_string("protocol_version", &proto)?; + js.set_object("startup_parameters", &log_startup_parameters(params)?)?; + } + PgsqlFEMessage::SSLRequest(_) => { + js.set_string("message", "SSL Request")?; + } + PgsqlFEMessage::SASLInitialResponse(SASLInitialResponsePacket { + identifier: _, + length: _, + auth_mechanism, + param_length: _, + sasl_param, + }) => { + js.set_string("sasl_authentication_mechanism", auth_mechanism.to_str())?; + js.set_string_from_bytes("sasl_param", sasl_param)?; + } + PgsqlFEMessage::PasswordMessage(RegularPacket { + identifier: _, + length: _, + payload, + }) => { + if flags & PGSQL_LOG_PASSWORDS != 0 { + js.set_string_from_bytes(req.to_str(), payload)?; + } else { + js.set_bool("password_redacted", true)?; + } + } + PgsqlFEMessage::SASLResponse(RegularPacket { + identifier: _, + length: _, + payload, + }) => { + js.set_string_from_bytes("sasl_response", payload)?; + } + PgsqlFEMessage::SimpleQuery(RegularPacket { + identifier: _, + length: _, + payload, + }) => { js.set_string_from_bytes(req.to_str(), payload)?; - } else { - js.set_bool("password_redacted", true)?; } - } - PgsqlFEMessage::SASLResponse(RegularPacket { - identifier: _, - length: _, - payload, - }) => { - js.set_string_from_bytes("sasl_response", payload)?; - } - PgsqlFEMessage::SimpleQuery(RegularPacket { - identifier: _, - length: _, - payload, - }) - | PgsqlFEMessage::CopyFail(RegularPacket { - identifier: _, - length: _, - payload, - }) => { - js.set_string_from_bytes(req.to_str(), payload)?; - } - PgsqlFEMessage::CancelRequest(CancelRequestMessage { pid, backend_key }) => { - js.set_string("message", "cancel_request")?; - js.set_uint("process_id", *pid)?; - js.set_uint("secret_key", *backend_key)?; - } - PgsqlFEMessage::ConsolidatedCopyDataIn(ConsolidatedDataRowPacket { - identifier: _, - row_cnt, - data_size, - }) => { - js.open_object(req.to_str())?; - js.set_uint("msg_count", *row_cnt)?; - js.set_uint("data_size", *data_size)?; - js.close()?; - } - PgsqlFEMessage::CopyDone(_) - | PgsqlFEMessage::Terminate(_) => { - js.set_string("message", req.to_str())?; - } - PgsqlFEMessage::UnknownMessageType(RegularPacket { - identifier: _, - length: _, - payload: _, - }) => { - // We don't want to log these, for now. Cf redmine: #6576 + PgsqlFEMessage::CopyFail(RegularPacket { + identifier: _, + length: _, + payload, + }) => { + js.set_string_from_bytes(req.to_str(), payload)?; + duplicated_messages[0] += 1; + debug_validate_bug_on!(duplicated_messages[0] > 1); + } + PgsqlFEMessage::CancelRequest(CancelRequestMessage { pid, backend_key }) => { + js.set_string("message", "cancel_request")?; + js.set_uint("process_id", *pid)?; + js.set_uint("secret_key", *backend_key)?; + } + PgsqlFEMessage::ConsolidatedCopyDataIn(ConsolidatedDataRowPacket { + identifier: _, + row_cnt, + data_size, + }) => { + js.open_object(req.to_str())?; + js.set_uint("msg_count", *row_cnt)?; + js.set_uint("data_size", *data_size)?; + js.close()?; + duplicated_messages[1] += 1; + debug_validate_bug_on!(duplicated_messages[1] > 1); + } + PgsqlFEMessage::CopyDone(_) => { + js.set_string("message", req.to_str())?; + duplicated_messages[2] += 1; + debug_validate_bug_on!(duplicated_messages[2] > 1); + } + PgsqlFEMessage::Terminate(_) => { + js.set_string("message", req.to_str())?; + } + PgsqlFEMessage::UnknownMessageType(RegularPacket { + identifier: _, + length: _, + payload: _, + }) => { + // We don't want to log these, for now. Cf redmine: #6576 + } } } Ok(())