Merge pull request #3003 in SNORT/snort3 from ~BSACHDEV/snort3:file_trace_infra to...

Squashed commit of the following:

commit a2d100df370abe5cbb31ae22d6221ba766d417e9
Author: bsachdev <bsachdev@cisco.com>
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 ed62773f04ab718e1d5f689d5f5f883d665937e8..045bb561226e16a7912e0d8d12606b60920e37f1 100644 (file)
--- 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<time_t>(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 12fddd49935f18670f8cce7b373edde59a354f35..2fc2d9fc008a359928a7114653d04b7acbf764c4 100644 (file)
--- 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 425b4cab49b2225ab0a0a4148ee47db28d834dc1..5afae3b5d39964487953727efabc6f61c9b2c46e 100644 (file)
--- 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 3e384f9b27077b368524abfb71c2353ef9d3ebdc..32925f0d09ba77edd5f3e47bef4d6c55ed6b128b 100644 (file)
--- 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 895c4f1432cadfb5a149e70aece87b33cb8eaa25..b5d86d93b673f86bfcffb26c1a850c93be065500 100644 (file)
--- 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 1d6b847fb4fcaf876aa336914f8585e19e8d7890..50b29c6af635eb94b3ebc37a514fa1b33c5b8e4a 100644 (file)
--- 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 7ed8dfabc22dc6b1419baf3e78360359855c1877..ebcde3a08cbec532395ea7501c544c56513255d4 100644 (file)
--- 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 9f0bd1e4b04011f8a9100be0f583e80740377926..f2ae621bd9d9b523e25e81ea31d469e390c1fcad 100644 (file)
--- 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());