From: Bhagya Tholpady (bbantwal) Date: Tue, 2 Jun 2020 16:06:08 +0000 (+0000) Subject: Merge pull request #2217 in SNORT/snort3 from ~SVLASIUK/snort3:module_track_time... X-Git-Tag: 3.0.1-5~36 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=d85fd04d11b3c66553a5e1505378f6039f6e0f4c;p=thirdparty%2Fsnort3.git Merge pull request #2217 in SNORT/snort3 from ~SVLASIUK/snort3:module_track_time to master Squashed commit of the following: commit acdd4a874962cfff0bb547009edcdb4163b2cd94 Author: Serhii Vlasiuk 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 5189b010e..2638cb141 100644 --- 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 f79879915..43d284409 100644 --- 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 33c10e6a3..8e3e1a533 100644 --- 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[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 d228da602..a908d3448 100644 --- 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 +static inline void trace_uprintf(const snort::Trace* trace, + TraceOptionID trace_option_id, const char* fmt, ...) __attribute__((format (printf, 3, 4))); + +template +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 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 #define trace_printf trace_printf +#define trace_uprintf trace_uprintf #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 a7c9a0890..a68685f19 100644 --- 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 11e12a545..313fbc2fa 100644 --- 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 9cff9f4f5..9bce7f08b 100644 --- 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 static inline void execute( Packet* p, PHInstance** prep, unsigned num) { + Stopwatch 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 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 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(p); + else + internal_execute(p); +} + +template +void InspectorManager::internal_execute(Packet* p) +{ + Stopwatch 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(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(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(p, fp_dft->network.vec, fp_dft->network.num); + ::execute(p, fp->network.vec, fp->network.num); if ( p->disable_inspect ) return; - ::execute(p, fp_dft->control.vec, fp_dft->control.num); + ::execute(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(p, fp_dft->network.vec, fp_dft->network.num); + ::execute(p, fp->network.vec, fp->network.num); } if ( p->disable_inspect ) return; if ( p->flow->full_inspection() ) - full_inspection(p); + full_inspection(p); if ( !p->disable_inspect and !p->flow->is_inspection_disabled() ) - ::execute(p, fp_dft->control.vec, fp_dft->control.num); + ::execute(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(p, fp->probe.vec, fp->probe.num); + else + { + Stopwatch 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(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 ffd9bb46c..7e3e3fe65 100644 --- 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 static void full_inspection(Packet*); + template static void internal_execute(Packet*); }; } #endif diff --git a/src/trace/trace_config.cc b/src/trace/trace_config.cc index 0fd1684fa..44ec62581 100644 --- 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 d229d620b..7ad3d94bb 100644 --- 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 c98b7f4f8..420f3612d 100644 --- 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());