From: Bhargava Jandhyala (bjandhya) Date: Fri, 30 Jul 2021 19:42:43 +0000 (+0000) Subject: Merge pull request #3003 in SNORT/snort3 from ~BSACHDEV/snort3:file_trace_infra to... X-Git-Tag: 3.1.10.0~12 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=5d716d4047878413e9db533939f6ad35d7066ff4;p=thirdparty%2Fsnort3.git Merge pull request #3003 in SNORT/snort3 from ~BSACHDEV/snort3:file_trace_infra to master Squashed commit of the following: commit a2d100df370abe5cbb31ae22d6221ba766d417e9 Author: bsachdev Date: Wed Jul 7 01:52:33 2021 -0400 file_api: Added infra and file debugs to existing debugging framework --- diff --git a/src/file_api/file_cache.cc b/src/file_api/file_cache.cc index ed62773f0..045bb5612 100644 --- a/src/file_api/file_cache.cc +++ b/src/file_api/file_cache.cc @@ -148,6 +148,8 @@ FileContext* FileCache::add(const FileHashKey& hashKey, int64_t timeout) * for key. This means bigger problems, but fail * gracefully. */ + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_CRITICAL_LEVEL, GET_CURRENT_PACKET, + "add:Insert failed in file cache, returning\n"); file_counts.cache_add_fails++; delete new_node.file; return nullptr; @@ -227,6 +229,9 @@ FileVerdict FileCache::check_verdict(Packet* p, FileInfo* file, assert(file); FileVerdict verdict = policy->type_lookup(p, file); + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "check_verdict:verdict after type lookup %d\n", verdict); + if (verdict == FILE_VERDICT_STOP_CAPTURE) { verdict = FILE_VERDICT_UNKNOWN; @@ -237,6 +242,8 @@ FileVerdict FileCache::check_verdict(Packet* p, FileInfo* file, verdict = policy->signature_lookup(p, file); } + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "check_verdict:verdict being returned %d\n", verdict); return verdict; } @@ -246,7 +253,11 @@ int FileCache::store_verdict(Flow* flow, FileInfo* file, int64_t timeout) uint64_t file_id = file->get_file_id(); if (!file_id) + { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_ERROR_LEVEL, GET_CURRENT_PACKET, + "store_verdict: file context doesn't have file id\n"); return 0; + } FileContext* file_got = get_file(flow, file_id, true, timeout); if (file_got) @@ -269,9 +280,11 @@ bool FileCache::apply_verdict(Packet* p, FileContext* file_ctx, FileVerdict verd timerclear(&file_ctx->pending_expire_time); file_ctx->verdict = verdict; + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, p, + "apply_verdict %d\n", verdict); + switch (verdict) { - case FILE_VERDICT_UNKNOWN: return false; case FILE_VERDICT_LOG: @@ -280,12 +293,16 @@ bool FileCache::apply_verdict(Packet* p, FileContext* file_ctx, FileVerdict verd return false; case FILE_VERDICT_BLOCK: // can't block session inside a session + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "apply_verdict:FILE_VERDICT_BLOCK with action block\n"); act->set_delayed_action(Active::ACT_BLOCK, true); act->set_drop_reason("file"); break; case FILE_VERDICT_REJECT: // can't reset session inside a session + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "apply_verdict:FILE_VERDICT_REJECT with action reset\n"); act->set_delayed_action(Active::ACT_RESET, true); act->set_drop_reason("file"); break; @@ -304,13 +321,21 @@ bool FileCache::apply_verdict(Packet* p, FileContext* file_ctx, FileVerdict verd // Block session on timeout if configured, otherwise use the // current action. if (fc->block_timeout_lookup) + { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "apply_verdict:FILE_VERDICT_PENDING with action reset\n"); act->set_delayed_action(Active::ACT_RESET, true); + } if (resume) policy->log_file_action(processing_flow, file_ctx, FILE_RESUME_BLOCK); else file_ctx->verdict = FILE_VERDICT_LOG; + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, p, + "File signature lookup: timed out after %" PRIi64 "ms.\n", + time_elapsed_ms(&now, &file_ctx->pending_expire_time, lookup_timeout)); + if (PacketTracer::is_active()) { PacketTracer::log("File signature lookup: timed out after %" PRIi64 "ms.\n", time_elapsed_ms(&now, &file_ctx->pending_expire_time, lookup_timeout)); @@ -325,6 +350,9 @@ bool FileCache::apply_verdict(Packet* p, FileContext* file_ctx, FileVerdict verd add_time = { static_cast(lookup_timeout), 0 }; timeradd(&now, &add_time, &file_ctx->pending_expire_time); + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, p, + "File signature lookup: adding new packet to retry queue.\n"); + if (PacketTracer::is_active()) PacketTracer::log("File signature lookup: adding new packet to retry queue.\n"); } @@ -336,20 +364,35 @@ bool FileCache::apply_verdict(Packet* p, FileContext* file_ctx, FileVerdict verd if (!(p->packet_flags & PKT_RETRANSMIT) or p->is_retry()) { PacketTracer::log("File signature lookup: adding packet to retry queue. Resume=%d, Waited %" PRIi64 "ms.\n", resume, time_elapsed_ms(&now, &file_ctx->pending_expire_time, lookup_timeout)); + + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, p, + "File signature lookup adding packet to retry queue" + "Resume=%d, Waited %" PRIi64 "ms.\n", resume, + time_elapsed_ms(&now, &file_ctx->pending_expire_time, lookup_timeout)); } } act->set_delayed_action(Active::ACT_RETRY, true); + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "apply_verdict:FILE_VERDICT_PENDING with action retry\n"); if (resume) policy->log_file_action(processing_flow, file_ctx, FILE_RESUME_BLOCK); else if (store_verdict(flow, file_ctx, lookup_timeout) != 0) + { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "apply_verdict:FILE_VERDICT_PENDING with action drop\n"); act->set_delayed_action(Active::ACT_DROP, true); + } else { FileFlows* files = FileFlows::get_file_flows(flow); if (files) + { files->add_pending_file(file_ctx->get_file_id()); + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "apply_verdict:Adding file id to pending\n"); + } } } return true; @@ -359,11 +402,17 @@ bool FileCache::apply_verdict(Packet* p, FileContext* file_ctx, FileVerdict verd if (resume) { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "apply_verdict:Resume block file\n"); file_ctx->log_file_event(flow, policy); policy->log_file_action(processing_flow, file_ctx, FILE_RESUME_BLOCK); } else if (file_ctx->is_cacheable()) + { store_verdict(flow, file_ctx, block_timeout); + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "apply_verdict:storing the file verdict\n"); + } return true; } @@ -377,16 +426,22 @@ FileVerdict FileCache::cached_verdict_lookup(Packet* p, FileInfo* file, assert(file); uint64_t file_id = file->get_file_id(); if (!file_id) + { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_ERROR_LEVEL, p, + "cached_verdict_lookup:File id not found, returning\n"); return verdict; + } FileContext* file_found = get_file(flow, file_id, false); if (file_found) { - // file_found might be a new context, set the flow here - file_found->set_processing_flow(flow); + // file_found might be a new context, set the flow here + file_found->set_processing_flow(flow); //Query the file policy in case verdict has been changed verdict = check_verdict(p, file_found, policy); + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "cached_verdict_lookup:Verdict received from cached_verdict_lookup %d\n", verdict); apply_verdict(p, file_found, verdict, true, policy); // Update the current file context from cached context *file = *(FileInfo*)file_found; diff --git a/src/file_api/file_flows.cc b/src/file_api/file_flows.cc index 12fddd499..2fc2d9fc0 100644 --- a/src/file_api/file_flows.cc +++ b/src/file_api/file_flows.cc @@ -35,6 +35,7 @@ #include "managers/inspector_manager.h" #include "packet_tracer/packet_tracer.h" #include "protocols/packet.h" +#include "main/snort_debug.h" #include "file_cache.h" #include "file_config.h" @@ -87,17 +88,27 @@ static void populate_trace_data(FileContext* context) void FileFlows::handle_retransmit(Packet* p) { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p , + "handle_retransmit:queried for verdict\n"); if (file_policy == nullptr) return; FileContext* file = get_file_context(pending_file_id, false); if ((file == nullptr) or (file->verdict != FILE_VERDICT_PENDING)) + { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_ERROR_LEVEL, p, + "handle_retransmit:context is null or verdict not pending, returning\n"); return; + } FileVerdict verdict = file_policy->signature_lookup(p, file); FileCache* file_cache = FileService::get_file_cache(); if (file_cache) + { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "handle_retransmit:applying file cache verdict %d\n", verdict); file_cache->apply_verdict(p, file, verdict, false, file_policy); + } file->log_file_event(flow, file_policy); } @@ -225,6 +236,8 @@ FileContext* FileFlows::get_file_context( FileCache* file_cache = FileService::get_file_cache(); assert(file_cache); context = file_cache->get_file(flow, file_id, false); + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, GET_CURRENT_PACKET, + "get_file_context:trying to get context from cache\n"); } // If we haven't found the context, create it and store it on the file flows object @@ -234,6 +247,8 @@ FileContext* FileFlows::get_file_context( FileConfig* fc = get_file_config(SnortConfig::get_conf()); if (partially_processed_contexts.size() == fc->max_files_per_flow) { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_ERROR_LEVEL, GET_CURRENT_PACKET, + "max file per flow limit reached %lu\n", partially_processed_contexts.size()); file_counts.files_over_flow_limit_not_processed++; events.create_event(EVENT_FILE_DROPPED_OVER_LIMIT); } @@ -243,6 +258,8 @@ FileContext* FileFlows::get_file_context( context->set_processing_flow(flow); partially_processed_contexts[multi_file_processing_id] = context; + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, GET_CURRENT_PACKET, + "get_file_context:creating new context\n"); if (partially_processed_contexts.size() > file_counts.max_concurrent_files_per_flow) file_counts.max_concurrent_files_per_flow = partially_processed_contexts.size(); } @@ -296,13 +313,19 @@ bool FileFlows::file_process(Packet* p, uint64_t file_id, const uint8_t* file_da if ((file_depth < 0) or (offset > (uint64_t)file_depth)) { + FILE_DEBUG(file_trace , DEFAULT_TRACE_OPTION_ID, TRACE_ERROR_LEVEL, p, + "file depth less than zero or offset is more than file depth , returning\n"); return false; } FileContext* context = get_file_context(file_id, true, multi_file_processing_id); if (!context) + { + FILE_DEBUG(file_trace , DEFAULT_TRACE_OPTION_ID, TRACE_CRITICAL_LEVEL, p, + "file_process:context missing, returning \n"); return false; + } if (PacketTracer::is_daq_activated()) PacketTracer::pt_timer_start(); @@ -340,6 +363,8 @@ bool FileFlows::file_process(Packet* p, uint64_t file_id, const uint8_t* file_da if ((context->get_file_sig_sha256()) || !context->is_file_signature_enabled()) { /* Just check file type and signature */ + FILE_DEBUG(file_trace , DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "calling context processing for position full\n"); continue_processing = context->process(p, file_data, data_size, SNORT_FILE_FULL, file_policy); if (context->processing_complete) @@ -350,6 +375,9 @@ bool FileFlows::file_process(Packet* p, uint64_t file_id, const uint8_t* file_da } } + FILE_DEBUG(file_trace , DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "calling context process data_size %d, offset %lu, position %d\n", + data_size, offset, position); continue_processing = context->process(p, file_data, data_size, offset, file_policy, position); if (context->processing_complete) remove_processed_file_context(multi_file_processing_id); @@ -370,10 +398,18 @@ bool FileFlows::file_process(Packet* p, const uint8_t* file_data, int data_size, FileDirection direction = upload ? FILE_UPLOAD : FILE_DOWNLOAD; /* if both disabled, return immediately*/ if (!FileService::is_file_service_enabled()) + { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_ERROR_LEVEL, p, + "file_process:file service not enabled, returning\n"); return false; + } if (position == SNORT_FILE_POSITION_UNKNOWN) + { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_ERROR_LEVEL, p, + "file_process:position of file is unknown, returning\n"); return false; + } if (PacketTracer::is_daq_activated()) PacketTracer::pt_timer_start(); diff --git a/src/file_api/file_lib.cc b/src/file_api/file_lib.cc index 425b4cab4..5afae3b5d 100644 --- a/src/file_api/file_lib.cc +++ b/src/file_api/file_lib.cc @@ -51,6 +51,7 @@ #include "file_service.h" #include "file_segment.h" #include "file_stats.h" +#include "file_module.h" using namespace snort; @@ -345,6 +346,8 @@ void FileContext::finish_signature_lookup(Packet* p, bool final_lookup, FilePoli if (get_file_sig_sha256()) { verdict = policy->signature_lookup(p, this); + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, + p, "finish signature lookup verdict %d\n", verdict); if ( verdict != FILE_VERDICT_UNKNOWN || final_lookup ) { FileCache* file_cache = FileService::get_file_cache(); @@ -414,6 +417,8 @@ bool FileContext::process(Packet* p, const uint8_t* file_data, int data_size, { update_file_size(data_size, position); processing_complete = true; + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, + p, "File: Type and Sig not enabled\n"); if (PacketTracer::is_active()) PacketTracer::log("File: Type and Sig not enabled\n"); return false; @@ -422,6 +427,8 @@ bool FileContext::process(Packet* p, const uint8_t* file_data, int data_size, if (cacheable and (FileService::get_file_cache()->cached_verdict_lookup(p, this, policy) != FILE_VERDICT_UNKNOWN)) { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, + p, "file process completed in file context process\n"); processing_complete = true; return true; } @@ -439,6 +446,8 @@ bool FileContext::process(Packet* p, const uint8_t* file_data, int data_size, update_file_size(data_size, position); processing_complete = true; stop_file_capture(); + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, p, + "File: Type unknown\n"); if (PacketTracer::is_active()) PacketTracer::log("File: Type unknown\n"); return false; @@ -446,13 +455,19 @@ bool FileContext::process(Packet* p, const uint8_t* file_data, int data_size, if (get_file_type() != SNORT_FILE_TYPE_CONTINUE) { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, p, + "File: Type-%s found\n", file_type_name(get_file_type()).c_str()); if (PacketTracer::is_active()) PacketTracer::log("File: Type-%s found\n", file_type_name(get_file_type()).c_str()); config_file_type(false); if (PacketTracer::is_active() and (!(is_file_signature_enabled()))) + { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, p, + "File: signature config is disabled\n"); PacketTracer::log("File: signature config is disabled\n"); + } file_stats->files_processed[get_file_type()][get_file_direction()]++; //Check file type based on file policy @@ -468,6 +483,8 @@ bool FileContext::process(Packet* p, const uint8_t* file_data, int data_size, if ( PacketTracer::is_active() and ( v == FILE_VERDICT_BLOCK or v == FILE_VERDICT_REJECT )) { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, p, + "File: file type verdict %s\n", v == FILE_VERDICT_BLOCK ? "block" : "reject"); PacketTracer::log("File: file type verdict %s\n", v == FILE_VERDICT_BLOCK ? "block" : "reject"); } @@ -480,6 +497,8 @@ bool FileContext::process(Packet* p, const uint8_t* file_data, int data_size, /* file signature calculation */ if (is_file_signature_enabled()) { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, p, + "file signature is enabled\n"); if (!sha256) process_file_signature_sha256(file_data, data_size, position); @@ -512,6 +531,8 @@ bool FileContext::process(Packet* p, const uint8_t* file_data, int data_size, } else { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, p, + "File: Sig depth exceeded\n"); if (PacketTracer::is_active()) PacketTracer::log("File: Sig depth exceeded\n"); return false; @@ -572,10 +593,14 @@ void FileContext::process_file_signature_sha256(const uint8_t* file_data, int da { if ((int64_t)processed_bytes + data_size > config->file_signature_depth) { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, GET_CURRENT_PACKET, + "process_file_signature_sha256:FILE_SIG_DEPTH_FAIL\n"); file_state.sig_state = FILE_SIG_DEPTH_FAIL; return; } + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, GET_CURRENT_PACKET, + "processing file signature position: %d sig state %d \n", position, file_state.sig_state); switch (position) { case SNORT_FILE_START: @@ -583,6 +608,8 @@ void FileContext::process_file_signature_sha256(const uint8_t* file_data, int da file_signature_context = snort_calloc(sizeof(SHA256_CTX)); SHA256_Init((SHA256_CTX*)file_signature_context); SHA256_Update((SHA256_CTX*)file_signature_context, file_data, data_size); + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, GET_CURRENT_PACKET, + "position is start of file\n"); if (file_state.sig_state == FILE_SIG_FLUSH) { static uint8_t file_signature_context_backup[sizeof(SHA256_CTX)]; @@ -598,6 +625,8 @@ void FileContext::process_file_signature_sha256(const uint8_t* file_data, int da if (!file_signature_context) return; SHA256_Update((SHA256_CTX*)file_signature_context, file_data, data_size); + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, GET_CURRENT_PACKET, + "position is middle of the file\n"); if (file_state.sig_state == FILE_SIG_FLUSH) { static uint8_t file_signature_context_backup[sizeof(SHA256_CTX)]; @@ -618,6 +647,8 @@ void FileContext::process_file_signature_sha256(const uint8_t* file_data, int da sha256 = new uint8_t[SHA256_HASH_SIZE]; SHA256_Final(sha256, (SHA256_CTX*)file_signature_context); file_state.sig_state = FILE_SIG_DONE; + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, GET_CURRENT_PACKET, + "position is end of the file\n"); break; case SNORT_FILE_FULL: @@ -628,6 +659,8 @@ void FileContext::process_file_signature_sha256(const uint8_t* file_data, int da sha256 = new uint8_t[SHA256_HASH_SIZE]; SHA256_Final(sha256, (SHA256_CTX*)file_signature_context); file_state.sig_state = FILE_SIG_DONE; + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, GET_CURRENT_PACKET, + "position is full file\n"); break; default: @@ -667,6 +700,11 @@ void FileContext::stop_file_capture() void FileContext::update_file_size(int data_size, FilePosition position) { processed_bytes += data_size; + + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, + GET_CURRENT_PACKET, + "Updating file size of file_id %lu at position %d with processed_bytes %lu\n", + file_id, position, processed_bytes); if ((position == SNORT_FILE_END)or (position == SNORT_FILE_FULL)) { file_size = processed_bytes; diff --git a/src/file_api/file_module.cc b/src/file_api/file_module.cc index 3e384f9b2..32925f0d0 100644 --- a/src/file_api/file_module.cc +++ b/src/file_api/file_module.cc @@ -33,12 +33,15 @@ #include "main/snort.h" #include "main/snort_config.h" #include "packet_io/active.h" +#include "trace/trace.h" #include "file_service.h" #include "file_stats.h" using namespace snort; +THREAD_LOCAL const Trace* file_trace = nullptr; + static const Parameter file_magic_params[] = { { "content", Parameter::PT_STRING, nullptr, nullptr, @@ -228,6 +231,15 @@ FileIdModule::~FileIdModule() delete fc; } +void FileIdModule::set_trace(const Trace* trace) const +{ file_trace = trace; } + +const TraceOption* FileIdModule::get_trace_options() const +{ + static const TraceOption filetrace_options(nullptr, 0, nullptr); + return &filetrace_options; +} + const PegInfo* FileIdModule::get_pegs() const { return file_pegs; } diff --git a/src/file_api/file_module.h b/src/file_api/file_module.h index 895c4f143..b5d86d93b 100644 --- a/src/file_api/file_module.h +++ b/src/file_api/file_module.h @@ -27,13 +27,21 @@ #include "file_config.h" #include "file_identifier.h" #include "file_policy.h" - +#include "main/snort_debug.h" +#include "utils/util.h" //------------------------------------------------------------------------- // file_id module //------------------------------------------------------------------------- static const uint32_t FILE_ID_GID = 150; +#define FILE_DEBUG(module_name, module_id, log_level, p, ...) \ + trace_logf(log_level, module_name , module_id, p, __VA_ARGS__) + +#define GET_CURRENT_PACKET snort::DetectionEngine::get_current_packet() + +extern THREAD_LOCAL const snort::Trace* file_trace; + class FileIdModule : public snort::Module { public: @@ -61,6 +69,8 @@ public: unsigned get_gid() const override { return FILE_ID_GID; } + void set_trace(const snort::Trace*) const override; + const snort::TraceOption* get_trace_options() const override; const snort::RuleMap* get_rules() const override; private: diff --git a/src/file_api/file_segment.cc b/src/file_api/file_segment.cc index 1d6b847fb..50b29c6af 100644 --- a/src/file_api/file_segment.cc +++ b/src/file_api/file_segment.cc @@ -24,6 +24,9 @@ #include "file_segment.h" #include "file_lib.h" +#include "file_module.h" + +#include "detection/detection_engine.h" using namespace snort; @@ -68,6 +71,9 @@ void FileSegments::add(const uint8_t* file_data, int64_t data_size, uint64_t off FileSegment* new_segment = new FileSegment(); new_segment->offset = offset; new_segment->data = new std::string((const char*)file_data, data_size); + FILE_DEBUG(file_trace , DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, + GET_CURRENT_PACKET , "Adding segment, offset : %u data_size : %lu\n", + new_segment->offset, data_size); head = new_segment; return; } @@ -134,6 +140,8 @@ void FileSegments::add(const uint8_t* file_data, int64_t data_size, uint64_t off // ignore overlap case if (data_size <= 0) { + FILE_DEBUG(file_trace , DEFAULT_TRACE_OPTION_ID, TRACE_ERROR_LEVEL, + GET_CURRENT_PACKET, "Complete overlap while adding segments\n"); return; } @@ -141,6 +149,9 @@ void FileSegments::add(const uint8_t* file_data, int64_t data_size, uint64_t off new_segment->offset = offset; new_segment->data = new std::string((const char*)file_data, data_size); + FILE_DEBUG(file_trace , DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, + GET_CURRENT_PACKET, "Adding offset : %u data_size : %lu\n", new_segment->offset, + data_size); if (!find_left) { previous->next = new_segment; @@ -190,6 +201,9 @@ int FileSegments::process_all(Packet* p, FilePolicyBase* policy) FileSegment* current_segment = head; while (current_segment && (current_offset == current_segment->offset)) { + FILE_DEBUG(file_trace, DEFAULT_TRACE_OPTION_ID, TRACE_INFO_LEVEL, + p, "processing the current offset %lu\n", current_offset); + ret = process_one(p, (const uint8_t*)current_segment->data->data(), current_segment->data->size(), policy); @@ -230,6 +244,9 @@ int FileSegments::process(Packet* p, const uint8_t* file_data, uint64_t data_siz } else { + FILE_DEBUG(file_trace , DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, + p, "not adding to file segment queue offset %lu , current_offset %lu\n", + offset , current_offset); return 1; } } diff --git a/src/service_inspectors/dce_rpc/dce_smb2.cc b/src/service_inspectors/dce_rpc/dce_smb2.cc index 7ed8dfabc..ebcde3a08 100644 --- a/src/service_inspectors/dce_rpc/dce_smb2.cc +++ b/src/service_inspectors/dce_rpc/dce_smb2.cc @@ -253,6 +253,8 @@ void Dce2Smb2SessionData::process_command(const Smb2Hdr* smb_hdr, Dce2SmbFlowData* fd = create_expected_smb_flow_data(p); if (fd) { + SMB_DEBUG(dce_smb_trace, DEFAULT_TRACE_OPTION_ID, TRACE_CRITICAL_LEVEL, GET_CURRENT_PACKET, + "Requesting for expected smb flow\n"); int result = Stream::set_snort_protocol_id_expected(p, PktType::TCP, IpProtocol::TCP, p->ptrs.ip_api.get_dst() , 0 ,p->ptrs.ip_api.get_src(), p->flow->server_port , snort_protocol_id_smb, fd, false, true); @@ -264,6 +266,11 @@ void Dce2Smb2SessionData::process_command(const Smb2Hdr* smb_hdr, delete fd; } } + else + { + SMB_DEBUG(dce_smb_trace, DEFAULT_TRACE_OPTION_ID, TRACE_CRITICAL_LEVEL, GET_CURRENT_PACKET, + "fd is null in negotiate , failed to create pinhole\n"); + } } } break; diff --git a/src/service_inspectors/dce_rpc/dce_smb_inspector.cc b/src/service_inspectors/dce_rpc/dce_smb_inspector.cc index 9f0bd1e4b..f2ae621bd 100644 --- a/src/service_inspectors/dce_rpc/dce_smb_inspector.cc +++ b/src/service_inspectors/dce_rpc/dce_smb_inspector.cc @@ -59,6 +59,9 @@ void Dce2Smb::show(const SnortConfig*) const void Dce2Smb::eval(Packet* p) { + SMB_DEBUG(dce_smb_trace, DEFAULT_TRACE_OPTION_ID, TRACE_DEBUG_LEVEL, + p, "smb packet detected with dsize as %u\n", p->dsize); + Profile profile(dce2_smb_pstat_main); assert(p->has_tcp_data());