Pull request #4992: flow: add logs to show different ways a flow can fail to create

Merge in SNORT/snort3 from ~JALIIMRA/snort3:pkt_without_flow_reason to master

Squashed commit of the following:

commit 67fdb4cf3c7bdfcc195b67f56111ca74c0af2d1b
Author: Juweria Ali Imran <jaliimra@cisco.com>
Date:   Thu Nov 6 10:23:43 2025 -0500

    flow: add logs to show different ways a flow can fail to create

diff --git a/src/flow/flow_cache.cc b/src/flow/flow_cache.cc
index e61092bb86fb73b8c3eab720c20e942eb077d46a..1dbe7006b88da96994527883369d9ca1b21b363d 100644 (file)
--- a/src/flow/flow_cache.cc
+++ b/src/flow/flow_cache.cc
@@ -393,10 +393,27 @@ Flow* FlowCache::allocate(const FlowKey* key)
     time_t timestamp = packet_time();
     if ( hash_table->get_num_nodes() >= config.max_flows )
     {
-        if ( !prune_idle(timestamp, nullptr) )
+        if ( PacketTracer::is_active() )
         {
-            if ( !prune_unis(key->pkt_type) )
-                prune_excess(nullptr);
+            PacketTracer::log("Flow: at max_flows limit (%u/%u), attempting to prune for new allocation\n",
+                hash_table->get_num_nodes(), config.max_flows);
+        }
+
+        unsigned pruned_idle = prune_idle(timestamp, nullptr);
+        if ( !pruned_idle )
+        {
+            unsigned pruned_uni = prune_unis(key->pkt_type);
+            if ( !pruned_uni )
+            {
+                unsigned pruned_excess = prune_excess(nullptr);
+                if ( PacketTracer::is_active() && !pruned_excess )
+                {
+                    // CRITICAL: All pruning strategies failed
+                    PacketTracer::log("Flow: CRITICAL - allocation at max capacity, no flows could be pruned "
+                        "(idle=0, uni=0, excess=0), current=%u, max=%u\n",
+                        hash_table->get_num_nodes(), config.max_flows);
+                }
+            }
         }
     }
 

diff --git a/src/flow/flow_control.cc b/src/flow/flow_control.cc
index bacdd1669f3d6ef2439a32a03535b137641485b9..98d046af1e4ac489d36faa8eb3e4785447ab9dd8 100644 (file)
--- a/src/flow/flow_control.cc
+++ b/src/flow/flow_control.cc
@@ -44,9 +44,12 @@
 #include "flow_cache.h"
 #include "ha.h"
 #include "session.h"
+#include "stream/base/stream_module.h"
 
 using namespace snort;
 
+extern THREAD_LOCAL BaseStats stream_base_stats;
+
 FlowControl::FlowControl(const FlowCacheConfig& fc)
 {
     cache = new FlowCache(fc);
@@ -161,6 +164,7 @@ void FlowControl::timeout_flows(unsigned max, time_t cur_time)
     cache->timeout(max, cur_time);
 }
 
+
 Flow* FlowControl::stale_flow_cleanup(FlowCache* cache, Flow* flow, Packet* p)
 {
     if ( p->pkth->flags & DAQ_PKT_FLAG_NEW_FLOW )
@@ -374,7 +378,7 @@ void FlowControl::init_proto(PktType type, InspectSsnFunc get_ssn)
     get_proto_session[to_utype(type)] = get_ssn;
 }
 
-static bool want_flow(PktType type, Packet* p)
+static bool want_flow(PktType type, Packet* p, bool count_stats = true)
 {
     if ( type != PktType::TCP )
         return true;
@@ -384,12 +388,26 @@ static bool want_flow(PktType type, Packet* p)
         // Do not start a new flow from a retry packet.
         p->active->drop_packet(p);
         p->disable_inspect = true;
+        if ( count_stats )
+        {
+            if ( PacketTracer::is_active() )
+                PacketTracer::log("Flow: packet without flow - retry packets cannot initiate new flows\n");
+            stream_base_stats.no_flow_retry_packet++;
+        }
         return false;
     }
 
     if ( p->ptrs.tcph->is_rst() )
+    {
         // guessing direction based on ports is misleading
+        if ( count_stats )
+        {
+            if ( PacketTracer::is_active() )
+                PacketTracer::log("Flow: packet without flow - TCP RST packets cannot initiate new flows\n");
+            stream_base_stats.no_flow_tcp_rst++;
+        }
         return false;
+    }
 
     if ( p->ptrs.tcph->is_syn_only() )
     {
@@ -404,9 +422,28 @@ static bool want_flow(PktType type, Packet* p)
     }
 
     if ( p->ptrs.tcph->is_syn_ack() or p->dsize )
-        return Stream::midstream_allowed(p, true);
+    {
+        bool allowed = Stream::midstream_allowed(p, true);
+        if ( !allowed && count_stats )
+        {
+            if ( PacketTracer::is_active() )
+                PacketTracer::log("Flow: packet without flow - midstream pickup rejected: SYN_ACK=%d, dsize=%u, require_3whs timeout exceeded\n",
+                    p->ptrs.tcph->is_syn_ack(), p->dsize);
+            stream_base_stats.no_flow_midstream_reject++;
+        }
+        return allowed;
+    }
 
     p->packet_flags |= PKT_FROM_CLIENT;
+
+    if ( count_stats )
+    {
+        if ( PacketTracer::is_active() )
+            PacketTracer::log("Flow: packet without flow - TCP packet without SYN options/SYN-ACK/data, require_3whs=%d\n",
+                Stream::require_3whs());
+        stream_base_stats.no_flow_unwanted++;
+    }
+
     return false;
 }
 
@@ -443,7 +480,12 @@ static void drop_stale_packet(snort::Packet *p, snort::Flow *flow)
 bool FlowControl::process(PktType type, Packet* p, bool* new_flow)
 {
     if ( !get_proto_session[to_utype(type)] )
+    {
+        if ( PacketTracer::is_active() )
+            PacketTracer::log("Flow: packet without flow - no protocol handler registered for PktType=%u\n", to_utype(type));
+        stream_base_stats.no_flow_no_proto_handler++;
         return false;
+    }
 
     FlowKey key;
     bool reversed = set_key(&key, p);
@@ -485,7 +527,10 @@ bool FlowControl::process(PktType type, Packet* p, bool* new_flow)
             flow = cache->allocate(&key);
 
             if ( !flow )
+            {
+                stream_base_stats.no_flow_alloc_failure++;
                 return true;
+            }
 
             if ( p->is_tcp() and p->ptrs.tcph->is_syn_ack() )
                 flow->flags.key_is_reversed = !reversed;
@@ -547,7 +592,7 @@ unsigned FlowControl::process(Flow* flow, Packet* p, bool new_ha_flow)
         if ( flow->flow_state == Flow::FlowState::INSPECT and !flow->session->precheck(p) )
         {
             // flow expired, must recheck eligibility
-            if ( !want_flow(flow->pkt_type, p) )
+            if ( !want_flow(flow->pkt_type, p, false) )
             {
                 flow->session_state |= STREAM_STATE_CLOSED;
                 return 0;  // flow will be deleted

diff --git a/src/flow/test/flow_cache_test.cc b/src/flow/test/flow_cache_test.cc
index 9ecd8edf1adfdb7d2ad5c139631966a5d8c9c63b..4ef0673c6da96b67f0ee87b42f4eefe46ec63a86 100644 (file)
--- a/src/flow/test/flow_cache_test.cc
+++ b/src/flow/test/flow_cache_test.cc
@@ -44,6 +44,7 @@
 #include "protocols/tcp.h"
 #include "protocols/udp.h"
 #include "protocols/vlan.h"
+#include "stream/base/stream_module.h"
 #include "utils/util.h"
 #include "trace/trace_api.h"
 
@@ -56,6 +57,7 @@ using namespace snort;
 
 THREAD_LOCAL const Trace* stream_trace = nullptr;
 THREAD_LOCAL FlowControl* flow_con = nullptr;
+THREAD_LOCAL BaseStats stream_base_stats = {};
 
 Analyzer* Analyzer::get_local_analyzer() { return nullptr; }
 void Analyzer::resume(uint64_t) { }

diff --git a/src/flow/test/flow_control_test.cc b/src/flow/test/flow_control_test.cc
index c05301357114cf8865a7489a791d2f0538551560..94bebc615e709acd3e15d6d7f05592789aecfb0b 100644 (file)
--- a/src/flow/test/flow_control_test.cc
+++ b/src/flow/test/flow_control_test.cc
@@ -36,6 +36,7 @@
 #include "protocols/tcp.h"
 #include "protocols/udp.h"
 #include "protocols/vlan.h"
+#include "stream/base/stream_module.h"
 #include "stream/stream.h"
 #include "utils/util.h"
 #include "flow/expect_cache.h"
@@ -89,6 +90,7 @@ Flow* HighAvailabilityManager::import(Packet&, FlowKey&) { return nullptr; }
 bool FlowCache::move_to_allowlist(snort::Flow*) { return true; }
 uint64_t FlowCache::get_lru_flow_count(uint8_t) const { return 0; }
 SO_PUBLIC void snort::ts_print(const struct timeval*, char*, bool) { }
+THREAD_LOCAL BaseStats stream_base_stats = {};
 
 namespace snort
 {
@@ -154,20 +156,20 @@ TEST(stale_flow, stale_flow)
     Flow* flow = new Flow;
     FlowCacheConfig fcg;
     FlowCache *cache = new FlowCache(fcg);
-    FlowControl *flow_con = new FlowControl(fcg);
+    FlowControl *flow_control = new FlowControl(fcg);
     DAQ_PktHdr_t dh = { };
 
     dh.flags = DAQ_PKT_FLAG_NEW_FLOW;
     p->pkth = &dh;
-    CHECK(flow_con->stale_flow_cleanup(cache, flow, p) == nullptr);
+    CHECK(flow_control->stale_flow_cleanup(cache, flow, p) == nullptr);
 
     dh.flags &= ~DAQ_PKT_FLAG_NEW_FLOW;
-    CHECK(flow_con->stale_flow_cleanup(cache, flow, p) == flow);
+    CHECK(flow_control->stale_flow_cleanup(cache, flow, p) == flow);
 
     p->pkth = nullptr;
     delete flow;
     delete p;
-    delete flow_con;
+    delete flow_control;
     delete cache;
 }
 

diff --git a/src/managers/inspector_manager.cc b/src/managers/inspector_manager.cc
index e52698b3e2375d593cbc56a3c620958a18bd9472..60af3bdfa03e61d50611123e461546818c99ec42 100644 (file)
--- a/src/managers/inspector_manager.cc
+++ b/src/managers/inspector_manager.cc
@@ -40,10 +40,12 @@
 #include "main/snort_config.h"
 #include "main/snort_module.h"
 #include "main/thread_config.h"
+#include "packet_io/packet_tracer.h"
 #include "protocols/packet.h"
 #include "profiler/profiler_defs.h"
 #include "pub_sub/intrinsic_event_ids.h"
 #include "search_engines/search_tool.h"
+#include "stream/base/stream_module.h"
 #include "target_based/snort_protocols.h"
 #include "time/clock_defs.h"
 #include "time/stopwatch.h"
@@ -1979,6 +1981,15 @@ inline void InspectorManager::internal_execute(Packet* p)
         SingleInstanceInspectorPolicy* ft = sc->policy_map->get_flow_tracking();
         if (ft->instance )
             ::execute<T>(p, &ft->instance, 1);
+        else
+        {
+            if ( !p->flow )
+            {
+                stream_base_stats.no_flow_no_inspector++;
+                if ( PacketTracer::is_active() )
+                    PacketTracer::log("Flow: packet without flow - no flow tracking inspector configured\n");
+            }
+        }
     }
 
     // must check between each ::execute()
@@ -1992,7 +2003,16 @@ inline void InspectorManager::internal_execute(Packet* p)
             DataBus::publish(intrinsic_pub_id, IntrinsicEventIds::FLOW_STATE_RELOADED, p, p->flow);
     }
     else
+    {
+        if ( p->has_paf_payload() )
+        {
+            stream_base_stats.no_flow_paf_no_flow++;
+            if ( PacketTracer::is_active() )
+                PacketTracer::log("Flow: packet without flow - PAF payload but flow was deleted/expired\n");
+        }
+
         DataBus::publish(intrinsic_pub_id, IntrinsicEventIds::PKT_WITHOUT_FLOW, p);
+    }
 
     FrameworkPolicy* fp = get_inspection_policy()->framework_policy;
     assert(fp);

diff --git a/src/managers/test/get_inspector_test.cc b/src/managers/test/get_inspector_test.cc
index 5ce0e8aafa4e87454be98461cd7356629fea7cec..37ca080af76d7f2089e5024543938a6defe54979 100644 (file)
--- a/src/managers/test/get_inspector_test.cc
+++ b/src/managers/test/get_inspector_test.cc
@@ -23,6 +23,8 @@
 
 #include <unordered_map>
 
+#include "packet_io/packet_tracer.h"
+#include "stream/base/stream_module.h"
 #include "get_inspector_stubs.h"
 
 #include <CppUTest/CommandLineTestRunner.h>
@@ -31,6 +33,11 @@
 
 using namespace snort;
 
+THREAD_LOCAL BaseStats stream_base_stats = {};
+
+bool PacketTracer::is_active() { return false; }
+void PacketTracer::log(const char*, ...) {}
+
 NetworkPolicy* snort::get_network_policy()
 { return (NetworkPolicy*)mock().getData("network_policy").getObjectPointer(); }
 NetworkPolicy* PolicyMap::get_user_network(uint64_t) const

diff --git a/src/stream/base/stream_base.cc b/src/stream/base/stream_base.cc
index df706971ff3f4869d5e46916dfcc4804b2537d84..18097c0c4bc5032a6fac8d53676d6bab863dcef0 100644 (file)
--- a/src/stream/base/stream_base.cc
+++ b/src/stream/base/stream_base.cc
@@ -32,6 +32,7 @@
 #include "main/snort_config.h"
 #include "main/snort_types.h"
 #include "managers/inspector_manager.h"
+#include "packet_io/packet_tracer.h"
 #include "profiler/profiler_defs.h"
 #include "protocols/packet.h"
 #include "protocols/tcp.h"
@@ -108,6 +109,17 @@ const PegInfo base_pegs[] =
     { CountType::SUM, "allowlist_eof_prunes", "number of allowlist flows pruned due to EOF" },
     { CountType::SUM, "excess_to_allowlist", "number of flows moved to the allowlist due to excess" },
 
+    // Flow creation failure counters
+    { CountType::SUM, "no_flow_no_proto_handler", "packets without flow: no protocol handler registered" },
+    { CountType::SUM, "no_flow_retry_packet", "packets without flow: retry packet dropped" },
+    { CountType::SUM, "no_flow_tcp_rst", "packets without flow: TCP RST packet" },
+    { CountType::SUM, "no_flow_unwanted", "packets without flow: flow not wanted" },
+    { CountType::SUM, "no_flow_midstream_reject", "packets without flow: midstream rejected" },
+    { CountType::SUM, "no_flow_alloc_failure", "packets without flow: flow allocation failed" },
+    { CountType::SUM, "no_flow_pkt_type_none", "packets without flow: packet type is NONE" },
+    { CountType::SUM, "no_flow_no_inspector", "packets without flow: no flow tracking inspector configured" },
+    { CountType::SUM, "no_flow_paf_no_flow", "packets without flow: PAF payload but no flow exists" },
+
     // Keep the NOW stats at the bottom as it requires special sum_stats logic
     { CountType::NOW, "allowlist_flows", "number of flows moved to the allowlist" },
     { CountType::NOW, "current_flows", "current number of flows in cache" },
@@ -314,6 +326,9 @@ void StreamBase::eval(Packet* p)
     switch ( p->type() )
     {
     case PktType::NONE:
+        stream_base_stats.no_flow_pkt_type_none++;
+        if ( PacketTracer::is_active() )
+            PacketTracer::log("Flow: packet without flow - packet type is NONE\n");
         break;
 
     case PktType::IP:

diff --git a/src/stream/base/stream_module.h b/src/stream/base/stream_module.h
index 89dd2552e94bd582c42587f035fdde2599f80290..d69ad146461925d082157164d3b5421b52d34f48 100644 (file)
--- a/src/stream/base/stream_module.h
+++ b/src/stream/base/stream_module.h
@@ -115,6 +115,17 @@ struct BaseStats
      PegCount allowlist_eof_prunes;
      PegCount excess_to_allowlist;
 
+     // Flow creation failure counters
+     PegCount no_flow_no_proto_handler;
+     PegCount no_flow_retry_packet;
+     PegCount no_flow_tcp_rst;
+     PegCount no_flow_unwanted;
+     PegCount no_flow_midstream_reject;
+     PegCount no_flow_alloc_failure;
+     PegCount no_flow_pkt_type_none;
+     PegCount no_flow_no_inspector;
+     PegCount no_flow_paf_no_flow;
+
      // Keep the NOW stats at the bottom as it requires special sum_stats logic
      PegCount allowlist_flows;
      PegCount current_flows;

diff --git a/src/stream/stream.cc b/src/stream/stream.cc
index e0dcea2e41144891f60b14f7ae74f870c232a6bb..8b0a287222417075bba13a59a9fd6cb72a5dc2b5 100644 (file)
--- a/src/stream/stream.cc
+++ b/src/stream/stream.cc
@@ -166,7 +166,16 @@ bool Stream::midstream_allowed(const Packet* p, bool alert)
         return true;
 
     if ( alert )
+    {
         DetectionEngine::queue_event(GID_STREAM_TCP, STREAM_TCP_NO_3WHS);
+        
+        if ( PacketTracer::is_active() )
+        {
+            time_t elapsed = p->pkth->ts.tv_sec - packet_first_time();
+            PacketTracer::log("Stream: midstream pickup disabled - require_3whs timeout exceeded "
+                "(hs_timeout=%d sec, elapsed=%ld sec since startup)\n", t, elapsed);
+        }
+    }
 
     return false;
 }