Merge pull request #2217 in SNORT/snort3 from ~SVLASIUK/snort3:module_track_time...

Squashed commit of the following:

commit acdd4a874962cfff0bb547009edcdb4163b2cd94
Author: Serhii Vlasiuk <svlasiuk@cisco.com>
Date:   Wed May 13 10:51:22 2020 +0300

    managers: add inspector execution and timing traces to InspectorManager

    Add snort module main and inspector_manager trace options.
    Remove --trace command line option.

diff --git a/src/framework/inspector.h b/src/framework/inspector.h
index 5189b010e0d4e48cf1c8e935e33b172cc94780d7..2638cb141531dde8d66891150b783e338a6d35ef 100644 (file)
--- a/src/framework/inspector.h
+++ b/src/framework/inspector.h
@@ -134,6 +134,12 @@ public:
 
     const char* get_name() const;
 
+    void set_alias_name(const char* name)
+    { alias_name = name; }
+
+    const char* get_alias_name() const
+    { return alias_name; }
+
     virtual bool is_control_channel() const
     { return false; }
 
@@ -155,6 +161,8 @@ private:
     const InspectApi* api = nullptr;
     std::atomic_uint* ref_count;
     SnortProtocolId snort_protocol_id = 0;
+    // FIXIT-E Use std::string to avoid storing a pointer to external std::string buffers
+    const char* alias_name = nullptr;
 };
 
 // at present there is no sequencing among like types except that appid

diff --git a/src/main.cc b/src/main.cc
index f798799155a160e9f39dd362773dea11ba8b655e..43d284409a055030b45d24a72c59d33948ef4dfb 100644 (file)
--- a/src/main.cc
+++ b/src/main.cc
@@ -214,7 +214,7 @@ bool Pig::queue_command(AnalyzerCommand* ac, bool orphan)
 
 #ifdef DEBUG_MSGS
     unsigned ac_ref_count = ac->get();
-    debug_logf(snort_trace, nullptr, "[%u] Queuing command %s for execution (refcount %u)\n",
+    debug_logf(snort_trace, TRACE_MAIN, nullptr, "[%u] Queuing command %s for execution (refcount %u)\n",
         idx, ac->stringify(), ac_ref_count);
 #else
     ac->get();
@@ -228,13 +228,13 @@ void Pig::reap_command(AnalyzerCommand* ac)
     unsigned ac_ref_count = ac->put();
     if (ac_ref_count == 0)
     {
-        debug_logf(snort_trace, nullptr, "[%u] Destroying completed command %s\n",
+        debug_logf(snort_trace, TRACE_MAIN, nullptr, "[%u] Destroying completed command %s\n",
             idx, ac->stringify());
         delete ac;
     }
 #ifdef DEBUG_MSGS
     else
-        debug_logf(snort_trace, nullptr, "[%u] Reaped ongoing command %s (refcount %u)\n",
+        debug_logf(snort_trace, TRACE_MAIN, nullptr, "[%u] Reaped ongoing command %s (refcount %u)\n",
             idx, ac->stringify(), ac_ref_count);
 #endif
 }
@@ -296,7 +296,7 @@ void snort::main_broadcast_command(AnalyzerCommand* ac, bool from_shell)
     unsigned dispatched = 0;
 
     ac = get_command(ac, from_shell);
-    debug_logf(snort_trace, nullptr, "Broadcasting %s command\n", ac->stringify());
+    debug_logf(snort_trace, TRACE_MAIN, nullptr, "Broadcasting %s command\n", ac->stringify());
 
     for (unsigned idx = 0; idx < max_pigs; ++idx)
     {
@@ -702,7 +702,7 @@ static void reap_commands()
     {
         AnalyzerCommand* ac = orphan_commands.front();
         orphan_commands.pop();
-        debug_logf(snort_trace, nullptr, "Destroying orphan command %s\n", ac->stringify());
+        debug_logf(snort_trace, TRACE_MAIN, nullptr, "Destroying orphan command %s\n", ac->stringify());
         delete ac;
     }
 }

diff --git a/src/main/snort_config.cc b/src/main/snort_config.cc
index 33c10e6a3e7fec64b68f51ed211eccf064c58c91..8e3e1a5336fb28e6f77e3ab1e022af31d3f51810 100644 (file)
--- a/src/main/snort_config.cc
+++ b/src/main/snort_config.cc
@@ -458,7 +458,6 @@ void SnortConfig::merge(SnortConfig* cmd_line)
     assert(!state);
     num_slots = offload_threads + ThreadConfig::get_instance_max();
     state = new std::vector<void*>[num_slots];
-    trace_config->merge_cmd_line(cmd_line->trace_config);
 }
 
 bool SnortConfig::verify() const

diff --git a/src/main/snort_debug.h b/src/main/snort_debug.h
index d228da602f3b0f931f10e11a6686c2601233c0b2..a908d3448458b181555e8de710d85de113926ff5 100644 (file)
--- a/src/main/snort_debug.h
+++ b/src/main/snort_debug.h
@@ -57,6 +57,23 @@ SO_PUBLIC void trace_vprintf(const char* name, TraceLevel log_level,
 
 using trace_func = void(const char*, TraceLevel, const char*, const char*, va_list);
 
+template <trace_func>
+static inline void trace_uprintf(const snort::Trace* trace,
+    TraceOptionID trace_option_id, const char* fmt, ...) __attribute__((format (printf, 3, 4)));
+
+template <trace_func trace_vprintf = snort::trace_vprintf>
+static inline void trace_uprintf(const snort::Trace* trace,
+    TraceOptionID trace_option_id, const char* fmt, ...)
+{
+    va_list ap;
+    va_start(ap, fmt);
+
+    const char* trace_option_name = trace->option_name(trace_option_id);
+    trace_vprintf(trace->module_name(), DEFAULT_TRACE_LOG_LEVEL, trace_option_name, fmt, ap);
+
+    va_end(ap);
+}
+
 template <trace_func>
 static inline void trace_printf(TraceLevel log_level,
     const snort::Trace* trace, TraceOptionID trace_option_id,
@@ -180,9 +197,11 @@ static inline void trace_print(const snort::Trace* trace, const snort::Packet* p
 
 #define trace_print trace_print<snort::trace_vprintf>
 #define trace_printf trace_printf<snort::trace_vprintf>
+#define trace_uprintf trace_uprintf<snort::trace_vprintf>
 
 #define trace_log(...) trace_print(__VA_ARGS__)
 #define trace_logf(...) trace_printf(__VA_ARGS__)
+#define trace_ulogf(...) trace_uprintf(__VA_ARGS__)
 
 #ifdef DEBUG_MSGS
 #define debug_log trace_log
@@ -193,4 +212,3 @@ static inline void trace_print(const snort::Trace* trace, const snort::Packet* p
 #endif
 
 #endif
-

diff --git a/src/main/snort_module.cc b/src/main/snort_module.cc
index a7c9a08900bc8a162cdb887d46a0d4f6d5016156..a68685f19a7bbea7b49d18adcd540c51ea86a697 100644 (file)
--- a/src/main/snort_module.cc
+++ b/src/main/snort_module.cc
@@ -178,6 +178,14 @@ static const Command snort_cmds[] =
 // cases the default must only be indicated in the help.
 //-------------------------------------------------------------------------
 
+static const TraceOption snort_trace_options[] =
+{
+    { "main", TRACE_MAIN, "enable main trace logging" },
+    { "inspector_manager", TRACE_INSPECTOR_MANAGER, "enable inspector manager trace logging" },
+
+    { nullptr, 0, nullptr }
+};
+
 static const Parameter s_params[] =
 {
     { "-?", Parameter::PT_STRING, "(optional)", nullptr,
@@ -653,8 +661,7 @@ void SnortModule::set_trace(const Trace* trace) const
 
 const TraceOption* SnortModule::get_trace_options() const
 {
-    static const TraceOption snort_trace_options(nullptr, 0, nullptr);
-    return &snort_trace_options;
+    return snort_trace_options;
 }
 
 bool SnortModule::begin(const char* fqn, int, SnortConfig*)
@@ -1096,9 +1103,6 @@ bool SnortModule::set(const char*, Value& v, SnortConfig* sc)
     else if ( v.is("--x2s") )
         x2s(v.get_string());
 
-    else if (v.is("--trace"))
-        sc->trace_config->enable_trace_snort();
-
     return true;
 }
 

diff --git a/src/main/snort_module.h b/src/main/snort_module.h
index 11e12a545c14de6bc9332e5b29e584a86e90aff8..313fbc2faabeb32a8a4ecea740546656dae59fd4 100644 (file)
--- a/src/main/snort_module.h
+++ b/src/main/snort_module.h
@@ -36,5 +36,11 @@ extern THREAD_LOCAL const snort::Trace* snort_trace;
 
 snort::Module* get_snort_module();
 
+enum
+{
+    TRACE_MAIN = 0,
+    TRACE_INSPECTOR_MANAGER
+};
+
 #endif
 

diff --git a/src/managers/inspector_manager.cc b/src/managers/inspector_manager.cc
index 9cff9f4f57d62f9e5b3ee910dea424c82bed2a3e..9bce7f08b3e651b19ed61ea080f78a5b3675f5fd 100644 (file)
--- a/src/managers/inspector_manager.cc
+++ b/src/managers/inspector_manager.cc
@@ -36,10 +36,14 @@
 #include "main/shell.h"
 #include "main/snort.h"
 #include "main/snort_config.h"
+#include "main/snort_debug.h"
+#include "main/snort_module.h"
 #include "main/thread_config.h"
 #include "search_engines/search_tool.h"
 #include "protocols/packet.h"
 #include "target_based/snort_protocols.h"
+#include "time/clock_defs.h"
+#include "time/stopwatch.h"
 
 #include "module_manager.h"
 
@@ -116,7 +120,10 @@ struct PHInstance
     { return ( a->pp_class.api.type < b->pp_class.api.type ); }
 
     void set_name(const char* s)
-    { name = s; }
+    {
+        name = s;
+        handler->set_alias_name(name.c_str());
+    }
 
     void set_reloaded(ReloadType val)
     { reload_type = val; }
@@ -1032,9 +1039,11 @@ void InspectorManager::print_config(SnortConfig* sc)
 // packet handling
 //-------------------------------------------------------------------------
 
+template<bool T>
 static inline void execute(
     Packet* p, PHInstance** prep, unsigned num)
 {
+    Stopwatch<SnortClock> timer;
     for ( unsigned i = 0; i < num; ++i, ++prep )
     {
         if ( p->packet_flags & PKT_PASS_RULE )
@@ -1048,6 +1057,15 @@ static inline void execute(
         if ( !p->flow && (ppc.api.type == IT_SERVICE) )
             break;
 
+        const char* inspector_name = nullptr;
+        if ( T )
+        {
+            timer.reset();
+            inspector_name = (*prep)->name.c_str();
+            trace_ulogf(snort_trace, TRACE_INSPECTOR_MANAGER, "enter %s\n", inspector_name);
+            timer.start();
+        }
+
         // FIXIT-L ideally we could eliminate PktType and just use
         // proto_bits but things like teredo need to be fixed up.
         if ( p->type() == PktType::NONE )
@@ -1057,6 +1075,10 @@ static inline void execute(
         }
         else if ( BIT((unsigned)p->type()) & ppc.api.proto_bits )
             (*prep)->handler->eval(p);
+
+        if ( T )
+            trace_ulogf(snort_trace, TRACE_INSPECTOR_MANAGER,
+                "exit %s, elapsed time: %" PRId64" usec\n", inspector_name, TO_USECS(timer.get()));
     }
 }
 
@@ -1076,6 +1098,7 @@ void InspectorManager::bumble(Packet* p)
         flow->session->restart(p);
 }
 
+template<bool T>
 void InspectorManager::full_inspection(Packet* p)
 {
     Flow* flow = p->flow;
@@ -1090,16 +1113,51 @@ void InspectorManager::full_inspection(Packet* p)
 
     else if ( flow->gadget && flow->gadget->likes(p) )
     {
-        flow->gadget->eval(p);
+        if ( !T )
+            flow->gadget->eval(p);
+        else
+        {
+            Stopwatch<SnortClock> timer;
+            const char* inspector_name = flow->gadget->get_alias_name();
+            trace_ulogf(snort_trace, TRACE_INSPECTOR_MANAGER, "enter %s\n", inspector_name);
+            timer.start();
+
+            flow->gadget->eval(p);
+
+            trace_ulogf(snort_trace, TRACE_INSPECTOR_MANAGER,
+                "exit %s, elapsed time: %" PRId64 "\n", inspector_name, TO_USECS(timer.get()));
+        }
+
         p->context->clear_inspectors = true;
     }
 }
 
 // FIXIT-M leverage knowledge of flow creation so that reputation (possibly a
 // new it_xxx) is run just once per flow (and all non-flow packets).
-
 void InspectorManager::execute(Packet* p)
 {
+    if ( trace_enabled(snort_trace, TRACE_INSPECTOR_MANAGER, DEFAULT_TRACE_LOG_LEVEL, p) )
+        internal_execute<true>(p);
+    else
+        internal_execute<false>(p);
+}
+
+template<bool T>
+void InspectorManager::internal_execute(Packet* p)
+{
+    Stopwatch<SnortClock> timer;
+    const char* packet_type = nullptr;
+    if ( T )
+    {
+        packet_type = p->is_rebuilt() ? "rebuilt" : "raw";
+
+        trace_ulogf(snort_trace, TRACE_INSPECTOR_MANAGER,
+            "start inspection, %s, packet %" PRId64", context %" PRId64"\n",
+            packet_type, p->context->packet_number, p->context->context_num);
+
+        timer.start();
+    }
+
     FrameworkPolicy* fp = get_inspection_policy()->framework_policy;
     assert(fp);
 
@@ -1109,7 +1167,7 @@ void InspectorManager::execute(Packet* p)
         // be elevated from inspector to framework component (it is just
         // a flow control wrapper) and use eval() instead of process()
         // for stream_*.
-        ::execute(p, fp->session.vec, fp->session.num);
+        ::execute<T>(p, fp->session.vec, fp->session.num);
         fp = get_inspection_policy()->framework_policy;
     }
     // must check between each ::execute()
@@ -1117,7 +1175,7 @@ void InspectorManager::execute(Packet* p)
         return;
 
     if ( !p->is_cooked() )
-        ::execute(p, fp->packet.vec, fp->packet.num);
+        ::execute<T>(p, fp->packet.vec, fp->packet.num);
 
     if ( p->disable_inspect )
         return;
@@ -1128,13 +1186,13 @@ void InspectorManager::execute(Packet* p)
     if ( !p->flow )
     {
         if (fp_dft != fp)
-            ::execute(p, fp_dft->network.vec, fp_dft->network.num);
-        ::execute(p, fp->network.vec, fp->network.num);
+            ::execute<T>(p, fp_dft->network.vec, fp_dft->network.num);
+        ::execute<T>(p, fp->network.vec, fp->network.num);
 
         if ( p->disable_inspect )
             return;
 
-        ::execute(p, fp_dft->control.vec, fp_dft->control.num);
+        ::execute<T>(p, fp_dft->control.vec, fp_dft->control.num);
     }
     else
     {
@@ -1144,26 +1202,49 @@ void InspectorManager::execute(Packet* p)
         if ( !p->flow->service )
         {
             if (fp_dft != fp)
-                ::execute(p, fp_dft->network.vec, fp_dft->network.num);
-            ::execute(p, fp->network.vec, fp->network.num);
+                ::execute<T>(p, fp_dft->network.vec, fp_dft->network.num);
+            ::execute<T>(p, fp->network.vec, fp->network.num);
         }
 
         if ( p->disable_inspect )
             return;
 
         if ( p->flow->full_inspection() )
-            full_inspection(p);
+            full_inspection<T>(p);
 
         if ( !p->disable_inspect and !p->flow->is_inspection_disabled() )
-            ::execute(p, fp_dft->control.vec, fp_dft->control.num);
+            ::execute<T>(p, fp_dft->control.vec, fp_dft->control.num);
     }
+
+    if ( T )
+        trace_ulogf(snort_trace, TRACE_INSPECTOR_MANAGER,
+            "stop inspection, %s, packet %" PRId64", context %" PRId64", total time: %" PRId64" usec\n",
+            packet_type, p->context->packet_number, p->context->context_num, TO_USECS(timer.get()));
 }
 
 void InspectorManager::probe(Packet* p)
 {
     InspectionPolicy* policy = p->context->conf->policy_map->get_inspection_policy(0);
     FrameworkPolicy* fp = policy->framework_policy;
-    ::execute(p, fp->probe.vec, fp->probe.num);
+
+    if ( !trace_enabled(snort_trace, TRACE_INSPECTOR_MANAGER, DEFAULT_TRACE_LOG_LEVEL, p) )
+        ::execute<false>(p, fp->probe.vec, fp->probe.num);
+    else
+    {
+        Stopwatch<SnortClock> timer;
+        const char* packet_type = p->is_rebuilt() ? "rebuilt" : "raw";
+        trace_ulogf(snort_trace, TRACE_INSPECTOR_MANAGER,
+            "post detection inspection, %s, packet %" PRId64", context %" PRId64"\n",
+            packet_type, p->context->packet_number, p->context->context_num);
+
+        timer.start();
+
+        ::execute<true>(p, fp->probe.vec, fp->probe.num);
+
+        trace_ulogf(snort_trace, TRACE_INSPECTOR_MANAGER,
+            "end inspection, %s, packet %" PRId64", context %" PRId64", total time: %" PRId64" usec\n",
+            packet_type, p->context->packet_number, p->context->context_num, TO_USECS(timer.get()));
+    }
 }
 
 void InspectorManager::clear(Packet* p)

diff --git a/src/managers/inspector_manager.h b/src/managers/inspector_manager.h
index ffd9bb46cd21f9ce241998c837d0e3525a5ba567..7e3e3fe65676ec5ee2b52c4b122c516fa0530cb7 100644 (file)
--- a/src/managers/inspector_manager.h
+++ b/src/managers/inspector_manager.h
@@ -95,7 +95,8 @@ public:
 
 private:
     static void bumble(Packet*);
-    static void full_inspection(Packet*);
+    template<bool T> static void full_inspection(Packet*);
+    template<bool T> static void internal_execute(Packet*);
 };
 }
 #endif

diff --git a/src/trace/trace_config.cc b/src/trace/trace_config.cc
index 0fd1684fac62fa5be8a3751f2742651b7fab8a88..44ec62581ff0b2a6454ad77d35288913e23f9672 100644 (file)
--- a/src/trace/trace_config.cc
+++ b/src/trace/trace_config.cc
@@ -67,14 +67,3 @@ void TraceConfig::setup_module_trace() const
         trace.set_module_trace();
 }
 
-void TraceConfig::enable_trace_snort()
-{ trace_snort_enabled = true; }
-
-void TraceConfig::merge_cmd_line(TraceConfig* trace_config)
-{
-    trace_snort_enabled = trace_config->trace_snort_enabled;
-    
-    if ( trace_snort_enabled )
-        set_trace("snort", DEFAULT_TRACE_OPTION_NAME, DEFAULT_TRACE_LOG_LEVEL);
-}
-

diff --git a/src/trace/trace_config.h b/src/trace/trace_config.h
index d229d620b5b5c9e8add556acf3fb843278380d8f..7ad3d94bb6fa5392509f4ab131a50d36f64009dd 100644 (file)
--- a/src/trace/trace_config.h
+++ b/src/trace/trace_config.h
@@ -34,9 +34,7 @@ public:
     TraceConfig();
     ~TraceConfig();
 
-    void enable_trace_snort();
     void setup_module_trace() const;
-    void merge_cmd_line(TraceConfig*);
     bool set_trace(const std::string& module_name,
         const std::string& trace_option_name, uint8_t trace_level);
 
@@ -44,7 +42,6 @@ public:
     snort::PacketConstraints* constraints = nullptr;
 
 private:
-    bool trace_snort_enabled = false;
     Traces traces;
 };
 

diff --git a/src/trace/trace_module.cc b/src/trace/trace_module.cc
index c98b7f4f82605bfa2134bc4410ab8ae539d6ce28..420f3612df78addaa6441c820b2d527691b47ee3 100644 (file)
--- a/src/trace/trace_module.cc
+++ b/src/trace/trace_module.cc
@@ -48,7 +48,7 @@ void TraceModule::generate_params()
     for ( const auto* module : modules )
     {
         const TraceOption* trace_options = module->get_trace_options();
-        if ( trace_options && strcmp(module->get_name(), "snort") != 0 )
+        if ( trace_options )
         {
             auto& module_trace_options = configured_trace_options[module->get_name()];
             std::string module_trace_help(module->get_name());