Pull request #4914: Unified batched logger

Merge in SNORT/snort3 from ~JALIIMRA/snort3:unified_batched_logger to master

Squashed commit of the following:

commit de7b21ebe1c04d596eb93501a8e28dd429892c85
Author: Juweria Ali Imran <jaliimra@cisco.com>
Date:   Sun Aug 31 08:02:00 2025 -0400

    log: use batched logger for all kinds of log messages in prod when log_buffer config enabled

diff --git a/src/log/batched_logger.cc b/src/log/batched_logger.cc
index 661c77d1e2e6afb0502ceadd51b51bb993157665..b853e2124fab9ea66819b9551a8540a4db65eaf3 100644 (file)
--- a/src/log/batched_logger.cc
+++ b/src/log/batched_logger.cc
@@ -29,12 +29,17 @@
 #include <pthread.h>
 #include <sched.h>
 
+#include "control/control.h"
 #include "control/control_mgmt.h"
+#include "main/analyzer_command.h"
 #include "main/snort_config.h"
 #include "main/thread_config.h"
+#include "time/periodic.h"
 #include "utils/snort_pcre.h"
 #include "utils/util.h"
 
+#define LOG_BYTE_LIMIT 4096
+
 namespace BatchedLogger
 {
 
@@ -44,6 +49,21 @@ std::thread BatchedLogManager::writer_thread;
 std::atomic<bool> BatchedLogManager::running(false);
 std::atomic<uint64_t> BatchQueue::overwrite_count(0);
 
+class BatchedLoggerPeriodicFlush : public snort::AnalyzerCommand
+{
+public:
+    BatchedLoggerPeriodicFlush(ControlConn* ctrl = nullptr)
+        : AnalyzerCommand(ctrl) {}
+
+    bool execute(Analyzer&, void**) override
+    {
+        BatchedLogManager::flush_thread_buffers();
+        return true;
+    }
+
+    const char* stringify() override { return "BATCHED_LOGGER_PERIODIC_FLUSH"; }
+};
+
 void LogBuffer::append(FILE* fh, bool use_syslog, const char* msg, size_t len)
 {
     if (size + len >= LOG_BUFFER_THRESHOLD)
@@ -193,7 +213,10 @@ void BatchedLogManager::shutdown()
 {
     if (!running)
         return;
+
+    stop_periodic_flush();
     flush_thread_buffers();
+
     running = false;
     queue.push({});
 
@@ -210,6 +233,8 @@ void BatchedLogManager::shutdown()
 
 void BatchedLogManager::log(FILE* fh, bool use_syslog, const char* msg, size_t len)
 {
+    assert(snort::SnortConfig::get_conf()->use_log_buffered());
+
     buffer.append(fh, use_syslog, msg, len);
     auto now = std::chrono::steady_clock::now();
     auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(now - buffer.last_flush_time);
@@ -221,12 +246,16 @@ void BatchedLogManager::log(FILE* fh, bool use_syslog, const char* msg, size_t l
 #endif
 }
 
-#if 0
 void BatchedLogManager::log(FILE* fh, bool use_syslog, const char* format, va_list& ap)
 {
-    static char temp[1024];
+    assert(snort::SnortConfig::get_conf()->use_log_buffered());
+
+    thread_local char temp[LOG_BYTE_LIMIT];
     int len = vsnprintf(temp, sizeof(temp), format, ap);
 
+    assert(len <= LOG_BYTE_LIMIT);
+    len = std::min(len, LOG_BYTE_LIMIT);
+
     buffer.append(fh, use_syslog, temp, len);
     auto now = std::chrono::steady_clock::now();
     auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(now - buffer.last_flush_time);
@@ -239,7 +268,23 @@ void BatchedLogManager::log(FILE* fh, bool use_syslog, const char* format, va_li
 #endif
 
 }
-#endif
+
+static void s_batched_logger_flush_handler(void*)
+{
+    BatchedLogManager::flush_thread_buffers();
+    main_broadcast_command(new BatchedLoggerPeriodicFlush());
+}
+
+void BatchedLogManager::start_periodic_flush()
+{
+    Periodic::register_handler(s_batched_logger_flush_handler, nullptr, 0, 250);
+}
+
+void BatchedLogManager::stop_periodic_flush()
+{
+    Periodic::unregister_handler(s_batched_logger_flush_handler);
+}
+
 void BatchedLogManager::flush_thread_buffers()
 {
     buffer.flush();
@@ -250,6 +295,11 @@ void BatchedLogManager::push_batch(LogBatch&& batch)
     queue.push(std::move(batch));
 }
 
+static bool is_packet_tracer_message(const char* data, size_t size)
+{
+        return memmem(data, size, "PktTracerDbg", 12) != nullptr;
+}
+
 void BatchedLogManager::print_batch(const LogBatch& batch)
 {
     static bool stop_trace = false;
@@ -263,8 +313,9 @@ void BatchedLogManager::print_batch(const LogBatch& batch)
     }
     if (stop_trace)
         return;
-
-    if (!s_filter.filter.empty())
+    
+    // Only apply filters to PacketTracer content
+    if (!s_filter.filter.empty() && is_packet_tracer_message(batch.data.data(), batch.size))
     {
         int rc = pcre2_match(
             s_filter.re, reinterpret_cast<PCRE2_SPTR>(batch.data.data()),
@@ -307,7 +358,7 @@ void BatchedLogManager::print_batch(const LogBatch& batch)
         }
     }
 #ifdef SHELL
-    if (stop_trace)
+    if (stop_trace && is_packet_tracer_message(batch.data.data(), batch.size))
         if (!ControlMgmt::send_command_to_socket("packet_tracer.disable()\n"))
             fprintf(stderr, "Batched_logger: Failed to send command to control socket\n");
 #endif
@@ -333,6 +384,9 @@ void BatchedLogManager::writer_thread_func()
 
 void BatchedLogManager::init()
 {
+    if (running)
+        return;
+
     running = true;
 
     snort::ThreadConfig* thread_config = snort::SnortConfig::get_conf()->thread_config;
@@ -346,6 +400,8 @@ void BatchedLogManager::init()
     sched_param sch_params;
     sch_params.sched_priority = 1;
     pthread_setschedparam(writer_thread.native_handle(), SCHED_OTHER, &sch_params);
+
+    start_periodic_flush();
 }
 
 } // namespace BatchedLogger

diff --git a/src/log/batched_logger.h b/src/log/batched_logger.h
index a68fd8aae4dc3be0b458d625868134612644117b..31c69da4a0f0bd6acc681927f66ddbe5bee7d6cf 100644 (file)
--- a/src/log/batched_logger.h
+++ b/src/log/batched_logger.h
@@ -88,10 +88,12 @@ public:
     static void init();
     static void shutdown();
     static void log(FILE* fh, bool use_syslog, const char* msg, size_t len);
-    //static void log(FILE* fh, bool use_syslog, const char* format, va_list& ap);
+    static void log(FILE* fh, bool use_syslog, const char* format, va_list& ap);
     static void flush_thread_buffers();
     static void push_batch(LogBatch&& batch);
     static void set_filter(const std::string& filter);
+    static void start_periodic_flush();
+    static void stop_periodic_flush();
 
 private:
     static thread_local LogBuffer buffer;

diff --git a/src/log/messages.cc b/src/log/messages.cc
index ded6c39f36ed8bceda1b6e6d615d4075a8e78349..0f41c67a6538cf22281d928e0457ad47ae1176c9 100644 (file)
--- a/src/log/messages.cc
+++ b/src/log/messages.cc
@@ -29,6 +29,7 @@
 #include <cassert>
 #include <cstring>
 
+#include "log/batched_logger.h"
 #include "main/snort_config.h"
 #include "main/thread.h"
 #include "parser/parser.h"
@@ -178,15 +179,25 @@ void ReloadError(const char* format, ...)
 
 static void WriteLogMessage(FILE* fh, bool prefer_fh, const char* format, va_list& ap)
 {
-    if ( prefer_fh or !SnortConfig::log_syslog() )
-    {
-        vfprintf(fh, format, ap);
-        return;
-    }
-    char buf[STD_BUF+1];
-    vsnprintf(buf, STD_BUF, format, ap);
-    buf[STD_BUF] = '\0';
-    syslog(LOG_DAEMON | LOG_NOTICE, "%s", buf);
+    const SnortConfig* sc = SnortConfig::get_conf();
+    
+    if ( sc && sc->use_log_buffered() )
+        {
+            bool syslog_option = ( prefer_fh or !SnortConfig::log_syslog() ) ? false : true;
+            BatchedLogger::BatchedLogManager::log(fh, syslog_option, format, ap);
+        }
+    else
+        {
+            if ( prefer_fh or !SnortConfig::log_syslog() )
+            {
+                vfprintf(fh, format, ap);
+                return;
+            }
+            char buf[STD_BUF+1];
+            vsnprintf(buf, STD_BUF, format, ap);
+            buf[STD_BUF] = '\0';
+            syslog(LOG_DAEMON | LOG_NOTICE, "%s", buf);
+        }
 }
 
 // print an info message to stdout or syslog

diff --git a/src/main/modules.cc b/src/main/modules.cc
index 18c9e01738275be2b9d2091b0d592187e878faaf..ace3756248d61ccb794b1f2760706313d3650064 100644 (file)
--- a/src/main/modules.cc
+++ b/src/main/modules.cc
@@ -46,6 +46,7 @@
 #include "host_tracker/host_cache_module.h"
 #include "js_norm/js_norm_module.h"
 #include "latency/latency_module.h"
+#include "log/batched_logger.h"
 #include "log/messages.h"
 #include "lua/lua.h"
 #include "managers/module_manager.h"
@@ -766,6 +767,9 @@ static const Parameter output_params[] =
     { "obfuscate", Parameter::PT_BOOL, nullptr, "false",
       "obfuscate the logged IP addresses (same as -O)" },
 
+    { "log_buffered", Parameter::PT_BOOL, nullptr, "false",
+      "enable buffered logging for all output" },
+
 #ifdef REG_TEST
     { "wide_hex_dump", Parameter::PT_BOOL, nullptr, "true",
 #else
@@ -840,6 +844,16 @@ bool OutputModule::set(const char*, Value& v, SnortConfig* sc)
 
     else if ( v.is("obfuscate") )
         v.update_mask(sc->output_flags, OUTPUT_FLAG__OBFUSCATE);
+    
+    else if ( v.is("log_buffered") )
+    {
+        if ( v.get_bool() )
+            BatchedLogger::BatchedLogManager::init();
+        else
+            BatchedLogger::BatchedLogManager::shutdown();
+
+        v.update_mask(sc->output_flags, OUTPUT_FLAG__LOG_BUFFERED);
+    }
 
     return true;
 }

diff --git a/src/main/snort.cc b/src/main/snort.cc
index d092f5a738d876c212eb5bc234717a86c3fe99ce..aff6f49cd19fcdaa143a838b648f1afc6d47f52c 100644 (file)
--- a/src/main/snort.cc
+++ b/src/main/snort.cc
@@ -93,7 +93,6 @@
 #include "catch/snort_catch.h"
 #endif
 
-#include "log/batched_logger.h"
 #include "snort_config.h"
 #include "thread_config.h"
 
@@ -435,7 +434,6 @@ void Snort::setup(int argc, char* argv[])
 
     init(argc, argv);
     const SnortConfig* sc = SnortConfig::get_conf();
-    BatchedLogger::BatchedLogManager::init();
 
     if ( sc->daemon_mode() )
         daemonize();

diff --git a/src/main/snort_config.h b/src/main/snort_config.h
index 015bb2f8bc35a0e51f64d391a5d43242749efff0..a49e4a63cc1414b642e24371385c9dc5f2ab7c51 100644 (file)
--- a/src/main/snort_config.h
+++ b/src/main/snort_config.h
@@ -100,6 +100,7 @@ enum OutputFlag
     OUTPUT_FLAG__WIDE_HEX          = 0x00000800,
 
     OUTPUT_FLAG__ALERT_REFS        = 0x00001000,
+    OUTPUT_FLAG__LOG_BUFFERED      = 0x00002000,
 };
 
 enum LoggingFlag
@@ -575,6 +576,9 @@ public:
     bool obfuscate() const
     { return output_flags & OUTPUT_FLAG__OBFUSCATE; }
 
+    bool use_log_buffered() const
+    { return output_flags & OUTPUT_FLAG__LOG_BUFFERED; }
+
     bool output_app_data() const
     { return output_flags & OUTPUT_FLAG__APP_DATA; }
 

diff --git a/src/packet_io/packet_tracer.cc b/src/packet_io/packet_tracer.cc
index 6d9772f65999a57efe27b6cbff376275123830f4..2db50f59b4642da9c5d038449583e8a863b4be2b 100644 (file)
--- a/src/packet_io/packet_tracer.cc
+++ b/src/packet_io/packet_tracer.cc
@@ -160,16 +160,21 @@ void PacketTracer::dump(Packet* p)
         const char* drop_reason = p->active->get_drop_reason();
         if (drop_reason)
             PacketTracer::log("Verdict Reason: %s, %s\n", drop_reason, p->active->get_action_string() );
-        if (s_pkt_trace->buff_len < max_buff_size - 1)
-            s_pkt_trace->buffer[s_pkt_trace->buff_len++] = '\n';
-        if (s_pkt_trace->log_fh && s_pkt_trace->log_fh != stdout)
+        if(!snort::SnortConfig::get_conf()->use_log_buffered())
+            LogMessage(s_pkt_trace->log_fh, "%s\n", s_pkt_trace->buffer);
+        else
         {
-            fprintf(s_pkt_trace->log_fh, "%.*s", s_pkt_trace->buff_len, s_pkt_trace->buffer);
-            fflush(s_pkt_trace->log_fh);
+            if (s_pkt_trace->buff_len < max_buff_size - 1)
+                s_pkt_trace->buffer[s_pkt_trace->buff_len++] = '\n';
+            if (s_pkt_trace->log_fh && s_pkt_trace->log_fh != stdout)
+            {
+                fprintf(s_pkt_trace->log_fh, "%.*s", s_pkt_trace->buff_len, s_pkt_trace->buffer);
+                fflush(s_pkt_trace->log_fh);
+            }
+            else
+                BatchedLogger::BatchedLogManager::log(s_pkt_trace->log_fh, SnortConfig::log_syslog(),
+                    s_pkt_trace->buffer, s_pkt_trace->buff_len);
         }
-        else
-            BatchedLogger::BatchedLogManager::log(s_pkt_trace->log_fh, SnortConfig::log_syslog(),
-                s_pkt_trace->buffer, s_pkt_trace->buff_len);
     }
 
     s_pkt_trace->reset(false);

diff --git a/src/packet_io/packet_tracer_module.cc b/src/packet_io/packet_tracer_module.cc
index 164fb8c5b4dadbe7905607f029cb19de71cf7c5a..e45e64fa6bb3678fac44814c4c5a76e31b4c17f8 100644 (file)
--- a/src/packet_io/packet_tracer_module.cc
+++ b/src/packet_io/packet_tracer_module.cc
@@ -166,7 +166,20 @@ static int enable(lua_State* L)
         constraints.set_bits |= PacketConstraints::SetBits::DST_PORT;
 
     std::string filter_str = regexstr ? regexstr : "";
-    if (!filter_str.empty()) filter_str = (stop_after_match ? "Y" : "N") + filter_str;
+    if (!filter_str.empty()) 
+    {
+        if (!snort::SnortConfig::get_conf()->use_log_buffered())
+        {
+            LogMessage("WARNING: Regex filtering requires log_buffered to be enabled.\n");
+            LogMessage("         Continuing with packet tracer but ignoring regex filter.\n");
+            LogMessage("         To enable regex filtering, add 'log_buffered = true' to output configuration.\n");
+            
+            filter_str.clear();
+        }
+        else
+            filter_str = (stop_after_match ? "Y" : "N") + filter_str;
+    }
+
     BatchedLogger::BatchedLogManager::set_filter(filter_str);
     main_broadcast_command(new PacketTracerDebug(&constraints), ControlConn::query_from_lua(L));
     return 0;

diff --git a/src/time/periodic.cc b/src/time/periodic.cc
index 795bd56b3b82c13312ce7b2a913b18ebddf0bfa7..39dd3a1ff4245e238e44fa0eaf68a58f84b3bd1a 100644 (file)
--- a/src/time/periodic.cc
+++ b/src/time/periodic.cc
@@ -66,6 +66,13 @@ void Periodic::check()
     }
 }
 
+void Periodic::unregister_handler(PeriodicHook hook)
+{
+    s_periodic_handlers.remove_if([hook](const PeriodicHookNode& node) {
+        return node.hook == hook;
+    });
+}
+
 void Periodic::unregister_all()
 { s_periodic_handlers.clear(); }
 

diff --git a/src/time/periodic.h b/src/time/periodic.h
index b79fb1f02d76d077015ea224893f0e8d504e4d56..ab573efbf82e0d43c1a5343e7733c7c7724d3835 100644 (file)
--- a/src/time/periodic.h
+++ b/src/time/periodic.h
@@ -33,6 +33,7 @@ public:
     static void register_handler(PeriodicHook, void*, uint16_t priority, uint32_t);
     static void check();
 
+    static void unregister_handler(PeriodicHook hook);
     static void unregister_all();
 };