From: Juweria Ali Imran (jaliimra) Date: Mon, 5 Jan 2026 16:19:03 +0000 (+0000) Subject: Pull request #4992: flow: add logs to show different ways a flow can fail to create X-Git-Tag: 3.10.1.0~8 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=5f074f1f0a711216732920618f36cf6c841d1e78;p=thirdparty%2Fsnort3.git 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 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 e61092bb8..1dbe7006b 100644 --- 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 bacdd1669..98d046af1 100644 --- 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 9ecd8edf1..4ef0673c6 100644 --- 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 c05301357..94bebc615 100644 --- 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 e52698b3e..60af3bdfa 100644 --- 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(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 5ce0e8aaf..37ca080af 100644 --- a/src/managers/test/get_inspector_test.cc +++ b/src/managers/test/get_inspector_test.cc @@ -23,6 +23,8 @@ #include +#include "packet_io/packet_tracer.h" +#include "stream/base/stream_module.h" #include "get_inspector_stubs.h" #include @@ -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 df706971f..18097c0c4 100644 --- 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 89dd2552e..d69ad1464 100644 --- 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 e0dcea2e4..8b0a28722 100644 --- 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; }