perf(protocol): skip string debug escaping when proto debug is off

output_escape() was called on every send_str/receive_str even when
LOG_DEBUG_PROTO logging was disabled, allocating and scanning the whole
payload for a line that log_debug_message() then discarded.  Add a
log_debug_enabled(flag) gate mirroring log_debug_message()'s own filter and
check it before escaping.  Redacted (secret) strings still log the same
<redacted> marker; no observable log output changes.
This commit is contained in:
2026-09-12 16:54:43 +02:00
parent 1ba6372017
commit 87585e9881
4 changed files with 30 additions and 2 deletions
+4
View File
@@ -27,6 +27,10 @@ uint32_t get_log_debug_flags(void) {
return current_debug_flags;
}
bool log_debug_enabled(LogDebugFlag flag) {
return current_log_level <= LOG_LEVEL_DEBUG && (current_debug_flags & flag) != 0;
}
void set_log_info_flags(uint32_t flags) {
info_flags = flags;
info_flags_explicit = true;
+4
View File
@@ -29,6 +29,10 @@ void log_perror(const char* context);
void set_log_level(LogLevel level);
void set_log_debug_flags(uint32_t flags);
uint32_t get_log_debug_flags(void);
/* True when a log_debug_message() call with the same flag would actually emit:
* the debug log level is enabled AND the flag is selected. Hot paths use this
* to skip expensive message formatting/escaping when the line is filtered. */
bool log_debug_enabled(LogDebugFlag flag);
void log_debug_message(LogDebugFlag flag, const char* message, ...);
void set_log_info_flags(uint32_t flags);
uint32_t get_log_info_flags(void);
+2 -2
View File
@@ -432,7 +432,7 @@ static bool protocol_send_str_impl(ProtocolSession* session, const char* data, b
return false;
if (redact) {
log_debug_message(LOG_DEBUG_PROTO, "Send String: <redacted>");
} else {
} else if (log_debug_enabled(LOG_DEBUG_PROTO)) {
char* escaped_data = output_escape(data, log_get_8_bit_output());
log_debug_message(LOG_DEBUG_PROTO, "Send String: %s",
escaped_data ? escaped_data : "<allocation failed>");
@@ -465,7 +465,7 @@ static char* protocol_receive_str_impl(ProtocolSession* session, bool redact) {
data[size] = '\0';
if (redact) {
log_debug_message(LOG_DEBUG_PROTO, "Received String: <redacted>");
} else {
} else if (log_debug_enabled(LOG_DEBUG_PROTO)) {
char* escaped_data = output_escape(data, log_get_8_bit_output());
log_debug_message(LOG_DEBUG_PROTO, "Received String: %s",
escaped_data ? escaped_data : "<allocation failed>");
+20
View File
@@ -128,6 +128,25 @@ static void test_log_message_formats() {
EXPECT_TRUE(true);
}
/* log_debug_enabled is the lazy-formatting gate for log_debug_message: it must
* be true only at DEBUG level with the requested flag selected, exactly
* mirroring the filter inside log_debug_message itself. */
static void test_log_debug_enabled_matches_gate() {
set_log_level(LOG_LEVEL_WARNING);
set_log_debug_flags(LOG_DEBUG_ALL);
EXPECT_FALSE(log_debug_enabled(LOG_DEBUG_PROTO));
set_log_level(LOG_LEVEL_DEBUG);
set_log_debug_flags(LOG_DEBUG_PROTO);
EXPECT_TRUE(log_debug_enabled(LOG_DEBUG_PROTO));
EXPECT_FALSE(log_debug_enabled(LOG_DEBUG_IO));
set_log_debug_flags(0);
EXPECT_FALSE(log_debug_enabled(LOG_DEBUG_PROTO));
set_log_debug_flags(LOG_DEBUG_ALL);
}
void test_log() {
test_log_message_debug();
test_log_message_info();
@@ -139,4 +158,5 @@ void test_log() {
test_log_filtering();
test_log_stderr_mode_all();
test_log_message_formats();
test_log_debug_enabled_matches_gate();
}