From: Lokesh Bevinamarad (lbevinam) Date: Tue, 9 Mar 2021 11:26:44 +0000 (+0000) Subject: Merge pull request #2763 in SNORT/snort3 from ~SMULKA/snort3:daq_trace to master X-Git-Tag: 3.1.2.0~6 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=ca39c898e1280d21a61624191aedc727e2a193b6;p=thirdparty%2Fsnort3.git Merge pull request #2763 in SNORT/snort3 from ~SMULKA/snort3:daq_trace to master Squashed commit of the following: commit 222b106f98bbade0ad7c89dbf526feea8fd1f46e Author: smulka Date: Sat Feb 20 15:35:35 2021 -0500 packet_tracer: Added daq buffer to hold daq logs --- diff --git a/src/flow/test/flow_cache_test.cc b/src/flow/test/flow_cache_test.cc index 1fb570f99..12ca11be9 100644 --- a/src/flow/test/flow_cache_test.cc +++ b/src/flow/test/flow_cache_test.cc @@ -59,7 +59,7 @@ PacketTracer::~PacketTracer() { } void PacketTracer::log(const char*, ...) { } void PacketTracer::open_file() { } void PacketTracer::dump_to_daq(Packet*) { } -void PacketTracer::reset() { } +void PacketTracer::reset(bool) { } void PacketTracer::pause() { } void PacketTracer::unpause() { } void Active::set_drop_reason(char const*) { } diff --git a/src/flow/test/flow_control_test.cc b/src/flow/test/flow_control_test.cc index b49bee6e0..7b5064d25 100644 --- a/src/flow/test/flow_control_test.cc +++ b/src/flow/test/flow_control_test.cc @@ -59,7 +59,7 @@ PacketTracer::~PacketTracer() = default; void PacketTracer::log(const char*, ...) { } void PacketTracer::open_file() { } void PacketTracer::dump_to_daq(Packet*) { } -void PacketTracer::reset() { } +void PacketTracer::reset(bool) { } void PacketTracer::pause() { } void PacketTracer::unpause() { } void Active::set_drop_reason(char const*) { } diff --git a/src/main/analyzer.cc b/src/main/analyzer.cc index fc7a8de59..2aa9e40b4 100644 --- a/src/main/analyzer.cc +++ b/src/main/analyzer.cc @@ -322,6 +322,9 @@ void Analyzer::post_process_daq_pkt_msg(Packet* p) PacketTracer::dump(p); } + if (PacketTracer::is_daq_activated()) + PacketTracer::daq_dump(p); + HighAvailabilityManager::process_update(p->flow, p); if (verdict != MAX_DAQ_VERDICT) diff --git a/src/main/test/stubs.h b/src/main/test/stubs.h index 703f4e6e6..984652f7f 100644 --- a/src/main/test/stubs.h +++ b/src/main/test/stubs.h @@ -171,6 +171,7 @@ void PacketTracer::thread_init() { } void PacketTracer::thread_term() { } void PacketTracer::log(const char*, ...) { } void PacketTracer::dump(Packet*) { } +void PacketTracer::daq_dump(Packet*) { } void PacketTracer::activate(const Packet&) { } void TraceApi::thread_init(const TraceConfig*) { } void TraceApi::thread_term() { } diff --git a/src/network_inspectors/packet_tracer/packet_tracer.cc b/src/network_inspectors/packet_tracer/packet_tracer.cc index 258ddaf45..d711facb6 100644 --- a/src/network_inspectors/packet_tracer/packet_tracer.cc +++ b/src/network_inspectors/packet_tracer/packet_tracer.cc @@ -53,6 +53,8 @@ using namespace snort; // FIXIT-M refactor the way this is used so all methods are members called against this pointer THREAD_LOCAL PacketTracer* snort::s_pkt_trace = nullptr; +THREAD_LOCAL Stopwatch* snort::pt_timer = nullptr; + // so modules can register regardless of when packet trace is activated static THREAD_LOCAL struct{ unsigned val = 0; } global_mutes; @@ -72,6 +74,9 @@ template void PacketTracer::_thread_init() if ( s_pkt_trace == nullptr ) s_pkt_trace = new T(); + if ( pt_timer == nullptr ) + pt_timer = new Stopwatch; + s_pkt_trace->mutes.resize(global_mutes.val, false); s_pkt_trace->open_file(); s_pkt_trace->user_enabled = config_status; @@ -88,6 +93,12 @@ void PacketTracer::thread_term() delete s_pkt_trace; s_pkt_trace = nullptr; } + + if (pt_timer) + { + delete pt_timer; + pt_timer = nullptr; + } } void PacketTracer::dump(char* output_buff, unsigned int len) @@ -99,7 +110,7 @@ void PacketTracer::dump(char* output_buff, unsigned int len) memcpy(output_buff, s_pkt_trace->buffer, (len < s_pkt_trace->buff_len + 1 ? len : s_pkt_trace->buff_len + 1)); - s_pkt_trace->reset(); + s_pkt_trace->reset(false); } void PacketTracer::dump(Packet* p) @@ -107,9 +118,6 @@ void PacketTracer::dump(Packet* p) if (is_paused()) return; - if (s_pkt_trace->daq_activated) - s_pkt_trace->dump_to_daq(p); - if ((s_pkt_trace->buff_len > 0) and (s_pkt_trace->user_enabled or s_pkt_trace->shell_enabled)) { @@ -119,7 +127,29 @@ void PacketTracer::dump(Packet* p) LogMessage(s_pkt_trace->log_fh, "%s\n", s_pkt_trace->buffer); } - s_pkt_trace->reset(); + s_pkt_trace->reset(false); +} + +void PacketTracer::daq_dump(Packet *p) +{ + if (is_paused()) + return; + + if (s_pkt_trace->daq_activated) + s_pkt_trace->dump_to_daq(p); + + s_pkt_trace->reset(true); +} + +void PacketTracer::daq_log(const char* format, ...) +{ + if (is_paused()) + return; + + va_list ap; + va_start(ap, format); + s_pkt_trace->log_va(format, ap, true); + va_end(ap); } void PacketTracer::log(const char* format, ...) @@ -129,7 +159,7 @@ void PacketTracer::log(const char* format, ...) va_list ap; va_start(ap, format); - s_pkt_trace->log_va(format, ap); + s_pkt_trace->log_va(format, ap, false); va_end(ap); } @@ -140,7 +170,7 @@ void PacketTracer::log(TracerMute mute, const char* format, ...) va_list ap; va_start(ap, format); - s_pkt_trace->log_va(format, ap); + s_pkt_trace->log_va(format, ap, false); va_end(ap); s_pkt_trace->mutes[mute] = true; @@ -203,7 +233,7 @@ void PacketTracer::activate(const Packet& p) else s_pkt_trace->daq_activated = false; - if (s_pkt_trace->daq_activated or s_pkt_trace->user_enabled or s_pkt_trace->shell_enabled) + if (s_pkt_trace->user_enabled or s_pkt_trace->shell_enabled) { if (!p.ptrs.ip_api.is_ip()) { @@ -226,6 +256,12 @@ void PacketTracer::activate(const Packet& p) s_pkt_trace->active = false; } +void PacketTracer::pt_timer_start() +{ + pt_timer->reset(); + pt_timer->start(); +} + // ----------------------------------------------------------------------------- // non-static functions // ----------------------------------------------------------------------------- @@ -240,11 +276,22 @@ PacketTracer::~PacketTracer() } } -void PacketTracer::log_va(const char* format, va_list ap) +void PacketTracer::populate_buf(const char* format, va_list ap, char* buffer, uint32_t& buff_len) +{ + const int buff_space = max_buff_size - buff_len; + const int len = vsnprintf(buffer + buff_len, buff_space, format, ap); + + if (len >= 0 and len < buff_space) + buff_len += len; + else + buff_len = max_buff_size - 1; +} + +void PacketTracer::log_va(const char* format, va_list ap, bool daq_log) { // FIXIT-L Need to find way to add 'PktTracerDbg' string as part of format string. std::string dbg_str; - if (shell_enabled) // only add debug string during shell execution + if (shell_enabled and !daq_log) // only add debug string during shell execution { dbg_str = "PktTracerDbg "; if (strcmp(format, "\n") != 0) @@ -253,13 +300,10 @@ void PacketTracer::log_va(const char* format, va_list ap) format = dbg_str.c_str(); } - const int buff_space = max_buff_size - buff_len; - const int len = vsnprintf(buffer + buff_len, buff_space, format, ap); - - if (len >= 0 and len < buff_space) - buff_len += len; + if (daq_log) + s_pkt_trace->populate_buf(format, ap, daq_buffer, daq_buff_len); else - buff_len = max_buff_size - 1; + s_pkt_trace->populate_buf(format, ap, buffer, buff_len); } void PacketTracer::add_ip_header_info(const Packet& p) @@ -418,17 +462,26 @@ void PacketTracer::open_file() void PacketTracer::dump_to_daq(Packet* p) { assert(p); - p->daq_instance->set_packet_trace_data(p->daq_msg, (uint8_t *)buffer, buff_len + 1); + p->daq_instance->set_packet_trace_data(p->daq_msg, (uint8_t *)daq_buffer, daq_buff_len + 1); } -void PacketTracer::reset() +void PacketTracer::reset(bool daq_log) { - buff_len = 0; - buffer[0] = '\0'; + if ( daq_log ) + { + daq_buff_len = 0; + daq_buffer[0] = '\0'; + } + else + { + buff_len = 0; + buffer[0] = '\0'; - for ( unsigned i = 0; i < mutes.size(); i++ ) - mutes[i] = false; + for ( unsigned i = 0; i < mutes.size(); i++ ) + mutes[i] = false; + } } + // -------------------------------------------------------------------------- // unit tests // -------------------------------------------------------------------------- @@ -449,6 +502,12 @@ public: static unsigned int get_buff_len() { return ((TestPacketTracer*)s_pkt_trace)->buff_len; } + static char* get_daq_buff() + { return ((TestPacketTracer*)s_pkt_trace)->daq_buffer; } + + static unsigned int get_daq_buff_len() + { return ((TestPacketTracer*)s_pkt_trace)->daq_buff_len; } + static void set_user_enable(bool status) { ((TestPacketTracer*)s_pkt_trace)->user_enabled = status; } @@ -497,26 +556,59 @@ TEST_CASE("basic log", "[PacketTracer]") TestPacketTracer::thread_term(); } +TEST_CASE("basic daq log", "[PacketTracer]") +{ + char test_str[] = "1234567890"; + // instantiate a packet tracer + TestPacketTracer::thread_init(); + TestPacketTracer::pt_timer_start(); + TestPacketTracer::set_daq_enable(true); + TestPacketTracer::daq_log("%s", test_str); + CHECK(!(strcmp(TestPacketTracer::get_daq_buff(), test_str))); + CHECK((TestPacketTracer::get_daq_buff_len() == 10)); + TestPacketTracer::daq_log("%s", "ABCDEFG"); + CHECK((strcmp(TestPacketTracer::get_daq_buff(), "1234567890ABCDEFG") == 0)); + CHECK((TestPacketTracer::get_daq_buff_len() == strlen(TestPacketTracer::get_daq_buff()))); + + // log empty string won't change existed buffer + unsigned int curr_len = TestPacketTracer::get_daq_buff_len(); + char empty_str[] = ""; + TestPacketTracer::daq_log("%s", empty_str); + CHECK((TestPacketTracer::get_daq_buff_len() == curr_len)); + + TestPacketTracer::thread_term(); +} + TEST_CASE("corner cases", "[PacketTracer]") { char test_str[] = "1234567890", empty_str[] = ""; TestPacketTracer::thread_init(); TestPacketTracer::set_user_enable(true); + TestPacketTracer::set_daq_enable(true); // init length check CHECK((TestPacketTracer::get_buff_len() == 0)); + CHECK((TestPacketTracer::get_daq_buff_len() == 0)); // logging empty string to start with TestPacketTracer::log("%s", empty_str); CHECK((TestPacketTracer::get_buff_len() == 0)); + TestPacketTracer::daq_log("%s", empty_str); + CHECK((TestPacketTracer::get_daq_buff_len() == 0)); // log messages larger than buffer size for(int i=0; i<1024; i++) + { TestPacketTracer::log("%s", test_str); + TestPacketTracer::daq_log("%s", test_str); + } // when buffer limit is reached, buffer length will stopped at max_buff_size-1 CHECK((TestPacketTracer::get_buff_len() == (TestPacketTracer::max_buff_size-1))); + CHECK((TestPacketTracer::get_daq_buff_len() == (TestPacketTracer::max_buff_size-1))); // continue logging will not change anything TestPacketTracer::log("%s", test_str); CHECK((TestPacketTracer::get_buff_len() == (TestPacketTracer::max_buff_size-1))); + TestPacketTracer::daq_log("%s", test_str); + CHECK((TestPacketTracer::get_daq_buff_len() == (TestPacketTracer::max_buff_size-1))); TestPacketTracer::thread_term(); } diff --git a/src/network_inspectors/packet_tracer/packet_tracer.h b/src/network_inspectors/packet_tracer/packet_tracer.h index a9013417b..6890dd5da 100644 --- a/src/network_inspectors/packet_tracer/packet_tracer.h +++ b/src/network_inspectors/packet_tracer/packet_tracer.h @@ -32,6 +32,8 @@ #include "protocols/ipv6.h" #include "protocols/protocol_ids.h" #include "sfip/sf_ip.h" +#include "time/clock_defs.h" +#include "time/stopwatch.h" // %s %u -> %s %u %u AS=%u ID=%u GR=%hd-%hd // IPv6 Port -> IPv6 Port Proto AS=ASNum ID=InstanceNum GR=SrcGroupNum-DstGroupNum @@ -57,6 +59,7 @@ public: static void dump(char* output_buff, unsigned int len); static void dump(Packet*); + static void daq_dump(Packet*); static void configure(bool status, const std::string& file_name); static void set_constraints(const PacketConstraints* constraints); @@ -66,12 +69,16 @@ public: static SO_PUBLIC void unpause(); static SO_PUBLIC bool is_paused(); static SO_PUBLIC bool is_active(); + static SO_PUBLIC bool is_daq_activated(); static SO_PUBLIC TracerMute get_mute(); static SO_PUBLIC void log(const char* format, ...) __attribute__((format (printf, 1, 2))); static SO_PUBLIC void log(TracerMute, const char* format, ...) __attribute__((format (printf, 2, 3))); + static SO_PUBLIC void daq_log(const char* format, ...) __attribute__((format (printf, 1, 2))); + static SO_PUBLIC void pt_timer_start(); + protected: @@ -80,6 +87,8 @@ protected: std::vector mutes; char buffer[max_buff_size]; unsigned buff_len = 0; + char daq_buffer[max_buff_size]; + unsigned daq_buff_len = 0; unsigned pause_count = 0; bool user_enabled = false; @@ -94,7 +103,8 @@ protected: template static void _thread_init(); // non-static functions - void log_va(const char*, va_list); + void log_va(const char*, va_list, bool); + void populate_buf(const char*, va_list, char*, uint32_t&); void add_ip_header_info(const snort::Packet&); void add_eth_header_info(const snort::Packet&); void add_packet_type_info(const snort::Packet&); @@ -103,15 +113,18 @@ protected: virtual void open_file(); virtual void dump_to_daq(Packet*); - virtual void reset(); - + virtual void reset(bool); }; SO_PUBLIC extern THREAD_LOCAL PacketTracer* s_pkt_trace; +SO_PUBLIC extern THREAD_LOCAL Stopwatch* pt_timer; inline bool PacketTracer::is_active() { return s_pkt_trace ? s_pkt_trace->active : false; } +inline bool PacketTracer::is_daq_activated() +{ return s_pkt_trace ? s_pkt_trace->daq_activated : false; } + struct SO_PUBLIC PacketTracerSuspend { PacketTracerSuspend() diff --git a/src/time/clock_defs.h b/src/time/clock_defs.h index 95b2a7f34..82008ec87 100644 --- a/src/time/clock_defs.h +++ b/src/time/clock_defs.h @@ -27,6 +27,7 @@ using SnortClock = TscClock; #define DURA_ZERO 0 #define TO_TICKS(t) (t) #define TO_USECS(t) (t) +#define TO_NSECS(t) (t) #define TO_DURATION(v, t) (t) #else @@ -38,6 +39,7 @@ inline long clock_scale() { return 1; } #define DURA_ZERO Clock::duration::zero() #define TO_TICKS(t) (t.count()) #define TO_USECS(t) (std::chrono::duration_cast(t).count()) +#define TO_NSECS(t) (std::chrono::duration_cast(t).count()) #define TO_DURATION(v, t) (std::chrono::duration_cast(std::chrono::microseconds(t))) #endif