From: Bhagya Tholpady (bbantwal) Date: Tue, 27 Oct 2020 12:41:30 +0000 (+0000) Subject: Merge pull request #2561 in SNORT/snort3 from ~OKHOMIAK/snort3:trace_add_timestamps... X-Git-Tag: 3.0.3-4~3 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=4544f2c73f6b4f44196e00cb2a30109b49f4c4f7;p=thirdparty%2Fsnort3.git Merge pull request #2561 in SNORT/snort3 from ~OKHOMIAK/snort3:trace_add_timestamps to master Squashed commit of the following: commit 306574431a9c2ddc00edfa11f37ae29d3bd77222 Author: Oleksii Khomiakovskyi Date: Mon Oct 12 13:18:36 2020 +0300 trace: add timestamps in trace log messages for stdout logger --- diff --git a/doc/user/trace.txt b/doc/user/trace.txt index b2b1de00d..5b335543d 100644 --- a/doc/user/trace.txt +++ b/doc/user/trace.txt @@ -14,12 +14,13 @@ following parameters: output - configure the output method for trace messages modules - trace configuration for specific modules constraints - filter traces by the packet constraints - log_ntuple - on/off packet n-tuple info logging + ntuple - on/off packet n-tuple info logging + timestamp - on/off message timestamps logging The following lines, added in snort.lua, will enable trace messages for detection and codec modules. The messages will be printed to syslog if the packet filtering constraints match. Messages will be in extended format, -including n-tuple packet info at the beginning of each trace message. +including timestamp and n-tuple packet info at the beginning of each trace message. trace = { @@ -36,7 +37,8 @@ including n-tuple packet info at the beginning of each trace message. src_port = 100, dst_port = 200 }, - log_ntuple = true + ntuple = true, + timestamp = true } The trace module supports config reloading. Also, it's possible to set or clear @@ -210,7 +212,8 @@ The trace control channel command is a way how to configure module trace options and/or packet filter constraints directly during Snort run and without reloading the entire config. -Control channel also allow adjusting trace output format by setting log_ntuple switcher. +Control channel also allow adjusting trace output format by setting ntuple +and timestamp switchers. After entering the Snort shell, there are two commands available for the trace module: @@ -219,7 +222,9 @@ the trace module: trace.set({ modules = { all = N } }) - enable traces for all modules with verbosity level N - trace.set({ log_ntuple = true/false }) - on/off packet n-tuple info logging + trace.set({ ntuple = true/false }) - on/off packet n-tuple info logging + + trace.set({ timestamp = true/false }) - on/off timestamp logging trace.clear() - clear modules traces and constraints @@ -247,7 +252,7 @@ C – main (control) thread P – packet thread O – other thread -Setting the option - *log_ntuple* allows you to change the trace message format, +Setting the option - *ntuple* allows you to change the trace message format, expanding it with information about the processed packet. It will be added at the beginning, right after the thread type and instance ID, @@ -267,6 +272,20 @@ Where: Those info can be displayed only for IP packets. Port defaults to zero if a packet doesn't have it. +The *timestamp* option extends output format +by logging the message time in the next format: + + MM/DD-hh:mm:ss.SSSSSS + +Where: + + M – month + D – day + h – hours + m – minutes + s – seconds + S – milliseconds + ==== Example - Debugging rules using detection trace The detection engine is responsible for rule evaluation. Turning on the diff --git a/src/trace/dev_notes.txt b/src/trace/dev_notes.txt index afb85b2e3..9e9b1c91d 100644 --- a/src/trace/dev_notes.txt +++ b/src/trace/dev_notes.txt @@ -31,7 +31,8 @@ This directory contains the trace logger framework. output - create a concrete logger factory based on the output value (stdout/syslog). constraints - set packet constraints to use for trace filtering. modules - set modules trace level verbosity. - log_ntuple - on/off packet n-tuple info logging. + ntuple - on/off packet n-tuple info logging. + timestamp - on/off message time stamps. This is a built-in module (from coreinit.lua) @@ -46,8 +47,8 @@ This directory contains the trace logger framework. for setting/clearing trace configuration from the shell. Commands parameters are encapsulated in the TraceSwapParams class. Available commands: - 1) trace.set({ modules = {}, constraints = {}, log_ntuple = true/false }) - -- set new modules traces, constraints and log_ntuple option; + 1) trace.set({ modules = {}, constraints = {}, ntuple = true/false, timestamp = true/false }) + -- set new modules traces, constraints, ntuple and timestamp options; 2) trace.clear() -- clear modules traces and constraints. * TraceSwapParams diff --git a/src/trace/trace_api.cc b/src/trace/trace_api.cc index 24b81499b..48e72ded8 100644 --- a/src/trace/trace_api.cc +++ b/src/trace/trace_api.cc @@ -52,10 +52,13 @@ static void update_constraints(PacketConstraints* new_cs) g_packet_constraints = new_cs; } -static inline void set_ntuple(bool log_ntuple) +static inline void set_logger_options(const TraceConfig* trace_config) { if ( g_trace_logger ) - g_trace_logger->set_ntuple(log_ntuple); + { + g_trace_logger->set_ntuple(trace_config->ntuple); + g_trace_logger->set_timestamp(trace_config->timestamp); + } } void TraceApi::thread_init(const TraceConfig* trace_config) @@ -63,7 +66,7 @@ void TraceApi::thread_init(const TraceConfig* trace_config) if ( trace_config->logger_factory ) g_trace_logger = trace_config->logger_factory->instantiate(); - set_ntuple(trace_config->log_ntuple); + set_logger_options(trace_config); update_constraints(trace_config->constraints); trace_config->setup_module_trace(); } @@ -78,7 +81,7 @@ void TraceApi::thread_term() void TraceApi::thread_reinit(const TraceConfig* trace_config) { - set_ntuple(trace_config->log_ntuple); + set_logger_options(trace_config); update_constraints(trace_config->constraints); trace_config->setup_module_trace(); } diff --git a/src/trace/trace_config.cc b/src/trace/trace_config.cc index 04078f2fe..f2766d317 100644 --- a/src/trace/trace_config.cc +++ b/src/trace/trace_config.cc @@ -47,7 +47,8 @@ TraceConfig::TraceConfig(const TraceConfig& other) : TraceConfig() { traces = other.traces; - log_ntuple = other.log_ntuple; + ntuple = other.ntuple; + timestamp = other.timestamp; if ( other.constraints ) constraints = new PacketConstraints(*other.constraints); } diff --git a/src/trace/trace_config.h b/src/trace/trace_config.h index c20cf61d3..dba31b229 100644 --- a/src/trace/trace_config.h +++ b/src/trace/trace_config.h @@ -45,8 +45,11 @@ public: public: snort::TraceLoggerFactory* logger_factory = nullptr; snort::PacketConstraints* constraints = nullptr; - bool log_ntuple = false; + + bool ntuple = false; + bool timestamp = false; bool initialized = false; + private: Traces traces; }; diff --git a/src/trace/trace_logger.h b/src/trace/trace_logger.h index 61aba1f84..0ce74a0bf 100644 --- a/src/trace/trace_logger.h +++ b/src/trace/trace_logger.h @@ -35,10 +35,14 @@ public: uint8_t log_level, const char* trace_option, const Packet* p) = 0; void set_ntuple(bool flag) - { log_ntuple = flag; } + { ntuple = flag; } + + void set_timestamp(bool flag) + { timestamp = flag; } protected: - bool log_ntuple = false; + bool ntuple = false; + bool timestamp = false; }; class TraceLoggerFactory diff --git a/src/trace/trace_loggers.cc b/src/trace/trace_loggers.cc index 4c74c3618..16d6742f4 100644 --- a/src/trace/trace_loggers.cc +++ b/src/trace/trace_loggers.cc @@ -28,6 +28,7 @@ #include "main/thread.h" #include "protocols/packet.h" +#include "utils/util.h" using namespace snort; @@ -35,9 +36,9 @@ using namespace snort; // Loggers //----------------------------------------------- -static std::string get_ntuple(bool log_ntuple, const Packet* p) +static std::string get_ntuple(bool ntuple, const Packet* p) { - if ( !log_ntuple or !p or !p->has_ip() ) + if ( !ntuple or !p or !p->has_ip() ) return ""; SfIpString src_addr; @@ -62,6 +63,17 @@ static std::string get_ntuple(bool log_ntuple, const Packet* p) return ss.str(); } +static std::string get_timestamp(bool timestamp) +{ + if ( !timestamp ) + return ""; + + char ts[TIMEBUF_SIZE]; + ts_print(nullptr, ts); + + return std::string(ts) + ":"; +} + // Stdout class StdoutTraceLogger : public TraceLogger @@ -98,8 +110,9 @@ StdoutTraceLogger::StdoutTraceLogger() void StdoutTraceLogger::log(const char* log_msg, const char* name, uint8_t log_level, const char* trace_option, const Packet* p) { - fprintf(file, "%c%u:%s%s:%s:%d: %s", thread_type, instance_id, - get_ntuple(log_ntuple, p).c_str(), name, trace_option, log_level, log_msg); + fprintf(file, "%s%c%u:%s%s:%s:%d: %s", get_timestamp(timestamp).c_str(), + thread_type, instance_id, get_ntuple(ntuple, p).c_str(), + name, trace_option, log_level, log_msg); } // Syslog @@ -123,7 +136,7 @@ SyslogTraceLogger::SyslogTraceLogger() void SyslogTraceLogger::log(const char* log_msg, const char* name, uint8_t log_level, const char* trace_option, const Packet* p) { - syslog(priority, "%s%s:%s:%d: %s", get_ntuple(log_ntuple, p).c_str(), + syslog(priority, "%s%s:%s:%d: %s", get_ntuple(ntuple, p).c_str(), name, trace_option, log_level, log_msg); } diff --git a/src/trace/trace_module.cc b/src/trace/trace_module.cc index b0c4b5a00..88cf8cf44 100644 --- a/src/trace/trace_module.cc +++ b/src/trace/trace_module.cc @@ -147,8 +147,11 @@ void TraceModule::generate_params() { "output", Parameter::PT_ENUM, "stdout | syslog", nullptr, "output method for trace log messages" }, - { "log_ntuple", Parameter::PT_BOOL, nullptr, "false", - "use extended trace output with n-tuple packet info" }, + { "ntuple", Parameter::PT_BOOL, nullptr, "false", + "print packet n-tuple info with trace messages" }, + + { "timestamp", Parameter::PT_BOOL, nullptr, "false", + "print message timestamps with trace messages" }, { nullptr, Parameter::PT_MAX, nullptr, nullptr, nullptr } }; @@ -189,9 +192,14 @@ bool TraceModule::set(const char* fqn, Value& v, SnortConfig*) } return true; } - else if ( v.is("log_ntuple") ) + else if ( v.is("ntuple") ) + { + trace_parser->get_trace_config().ntuple = v.get_bool(); + return true; + } + else if ( v.is("timestamp") ) { - trace_parser->get_trace_config().log_ntuple = v.get_bool(); + trace_parser->get_trace_config().timestamp = v.get_bool(); return true; } else if ( strstr(fqn, "trace.modules.") == fqn ) diff --git a/src/trace/trace_swap.cc b/src/trace/trace_swap.cc index d9a9715b6..a57c5830e 100644 --- a/src/trace/trace_swap.cc +++ b/src/trace/trace_swap.cc @@ -45,11 +45,13 @@ static int clear(lua_State*); void TraceSwapParams::set_params(const Parameter* params) { - const Parameter* ntuple_params = Parameter::find(params, "log_ntuple"); + const Parameter* ntuple_params = Parameter::find(params, "ntuple"); + const Parameter* timestamp_params = Parameter::find(params, "timestamp"); const Parameter* modules_params = Parameter::find(params, "modules"); const Parameter* constraints_params = Parameter::find(params, "constraints"); assert(ntuple_params); + assert(timestamp_params); assert(modules_params); assert(constraints_params); @@ -61,12 +63,15 @@ void TraceSwapParams::set_params(const Parameter* params) *ntuple_params, + *timestamp_params, + { nullptr, Parameter::PT_MAX, nullptr, nullptr, nullptr } }; static const Command commands[] = { - { "set", set, trace_params, "set modules traces, constraints and log_ntuple option" }, + { "set", set, trace_params, + "set modules traces, constraints, ntuple and timestamp options" }, { "clear", clear, nullptr, "clear modules traces and constraints" }, @@ -83,15 +88,41 @@ const Command* TraceSwapParams::get_commands() const Parameter* TraceSwapParams::get_params() { return s_params; } +struct LogParams +{ + bool set_traces; + bool set_constraints; + bool set_ntuple; + bool set_timestamp; + + bool is_set() const + { return set_traces or set_constraints or set_ntuple or set_timestamp; } + + void print_msg() const + { + if ( set_traces and set_constraints ) + LogMessage("== set modules traces and constraints\n"); + else if ( !is_set() ) + LogMessage("== clear modules traces and constraints\n"); + else if ( set_traces ) + LogMessage("== set modules traces\n"); + else if ( set_constraints ) + LogMessage("== set constraints\n"); + + if ( set_ntuple ) + LogMessage("== set ntuple option\n"); + + if ( set_timestamp ) + LogMessage("== set timestamp option\n"); + } +}; + class TraceSwap : public AnalyzerCommand { public: - TraceSwap(TraceConfig* tc, bool set_traces = false, bool set_constraints = false, - bool set_ntuple = false) + TraceSwap(TraceConfig* tc, const LogParams& lp) : trace_config(tc), - is_set_ntuple(set_ntuple), - is_set_traces(set_traces), - is_set_constraints(set_constraints) + log_params(lp) { assert(trace_config); } ~TraceSwap() override; @@ -99,14 +130,9 @@ public: const char* stringify() override { return "TRACE_SWAP"; } -private: - void print_msg() const; - private: TraceConfig* trace_config = nullptr; - bool is_set_ntuple; - bool is_set_traces; - bool is_set_constraints; + LogParams log_params; }; TraceSwap::~TraceSwap() @@ -116,7 +142,7 @@ TraceSwap::~TraceSwap() TraceApi::thread_reinit(trace_config); SnortConfig::get_main_conf()->set_overlay_trace_config(trace_config); - print_msg(); + log_params.print_msg(); } bool TraceSwap::execute(Analyzer&, void**) @@ -124,25 +150,10 @@ bool TraceSwap::execute(Analyzer&, void**) // Update configuration for packet threads TraceApi::thread_reinit(trace_config); - print_msg(); + log_params.print_msg(); return true; } -void TraceSwap::print_msg() const -{ - if ( is_set_traces and is_set_constraints ) - LogMessage("== set modules traces and constraints\n"); - else if ( !is_set_traces and !is_set_constraints and !is_set_ntuple ) - LogMessage("== clear modules traces and constraints\n"); - else if ( is_set_traces ) - LogMessage("== set modules traces\n"); - else if ( is_set_constraints ) - LogMessage("== set constraints\n"); - - if ( is_set_ntuple ) - LogMessage("== set log_ntuple option\n"); -} - static int set(lua_State* L) { const SnortConfig* sc = SnortConfig::get_conf(); @@ -159,14 +170,6 @@ static int set(lua_State* L) TraceConfig* trace_config = new TraceConfig(sc->overlay_trace_config ? *sc->overlay_trace_config : *sc->trace_config); - TraceParser trace_parser(*trace_config); - - const Parameter* params_tree = TraceSwapParams::get_params(); - bool parse_err = false; - bool set_traces = false; - bool set_constraints = false; - bool set_ntuple = false; - // Passed Lua entry check if ( lua_gettop(L) != 1 or !lua_istable(L, 1) ) { @@ -178,6 +181,11 @@ static int set(lua_State* L) return 0; } + TraceParser trace_parser(*trace_config); + const Parameter* params_tree = TraceSwapParams::get_params(); + LogParams log_params{}; + bool parse_err = false; + // Outer table traversal lua_pushnil(L); while ( lua_next(L, 1) ) @@ -185,17 +193,35 @@ static int set(lua_State* L) const char* root_element_key = luaL_checkstring(L, -2); const Parameter* root_parameter = Parameter::find(params_tree, root_element_key); - // extended output switcher + // log n-tuple if ( !strcmp(root_element_key, params_tree[2].name) ) { if ( lua_isboolean(L, -1) and root_parameter ) { - set_ntuple = true; - trace_parser.get_trace_config().log_ntuple = bool(lua_toboolean(L, -1)); + log_params.set_ntuple = true; + trace_parser.get_trace_config().ntuple = bool(lua_toboolean(L, -1)); + } + else + { + LogMessage("== invalid value for option: %s\n", root_element_key); + parse_err = true; + } + + lua_pop(L, 1); + continue; + } + + // log time stamp + if ( !strcmp(root_element_key, params_tree[3].name) ) + { + if ( lua_isboolean(L, -1) and root_parameter ) + { + log_params.set_timestamp = true; + trace_parser.get_trace_config().timestamp = bool(lua_toboolean(L, -1)); } else { - LogMessage("== invalid value is provided: %s\n", root_element_key); + LogMessage("== invalid value for option: %s\n", root_element_key); parse_err = true; } @@ -214,7 +240,7 @@ static int set(lua_State* L) // "modules" table traversal else if ( !strcmp(root_element_key, params_tree[0].name) ) { - set_traces = true; + log_params.set_traces = true; trace_parser.clear_traces(); const Parameter* modules_param = (const Parameter*)root_parameter->range; @@ -288,7 +314,7 @@ static int set(lua_State* L) // "constraints" table traversal else if ( !strcmp(root_element_key, params_tree[1].name) ) { - set_constraints = true; + log_params.set_constraints = true; trace_parser.clear_constraints(); const Parameter* constraints_param = (const Parameter*)root_parameter->range; @@ -327,18 +353,17 @@ static int set(lua_State* L) if ( !parse_err ) { - if ( !set_traces and !set_constraints and !set_ntuple ) + if ( !log_params.is_set() ) { trace_parser.clear_traces(); trace_parser.clear_constraints(); } - if ( set_constraints ) + if ( log_params.set_constraints ) trace_parser.finalize_constraints(); main_broadcast_command(new TraceSwap( - &trace_parser.get_trace_config(), set_traces, set_constraints, set_ntuple), - true); + &trace_parser.get_trace_config(), log_params), true); } else delete trace_config; @@ -350,7 +375,7 @@ static int clear(lua_State*) { // Create an empty overlay TraceConfig // It will be set in a SnortConfig during TraceSwap execution and owned by it after - main_broadcast_command(new TraceSwap(new TraceConfig), true); + main_broadcast_command(new TraceSwap(new TraceConfig, {}), true); return 0; }