diff --git a/source/common/stats/thread_local_store.cc b/source/common/stats/thread_local_store.cc index adc56e8f18911..7b5463ac631d6 100644 --- a/source/common/stats/thread_local_store.cc +++ b/source/common/stats/thread_local_store.cc @@ -1130,15 +1130,22 @@ void ThreadLocalStoreImpl::evictUnused() { MetricBag metrics(scope->scope_id_); CentralCacheEntrySharedPtr& central_cache = scope->centralCacheMutableNoThreadAnalysis(); auto filter_unused = [](StatNameHashMap& unused_metrics) { - return [&unused_metrics](std::pair kv) { + return [&unused_metrics](const std::pair& kv) { const auto& [name, metric] = kv; + // Evictable scopes can contain counters, gauges, text-readouts, and histograms. For all + // the gauges we find in one, we treat them as up/down counters that become evictable + // when they hit zero. + if constexpr (std::is_same_v) { + if (metric->value() != 0) { + return false; + } + } if (metric->used()) { metric->markUnused(); return false; - } else { - unused_metrics.try_emplace(name, metric); - return true; } + unused_metrics.try_emplace(name, metric); + return true; }; }; absl::erase_if(central_cache->counters_, filter_unused(metrics.counters_)); diff --git a/source/extensions/access_loggers/stats/stats.cc b/source/extensions/access_loggers/stats/stats.cc index 5373f5f834b4a..ad986a94e9f6d 100644 --- a/source/extensions/access_loggers/stats/stats.cc +++ b/source/extensions/access_loggers/stats/stats.cc @@ -17,68 +17,6 @@ namespace { using Extensions::Matching::Actions::TransformStat::ActionContext; -class AccessLogState : public StreamInfo::FilterState::Object { -public: - AccessLogState(Stats::ScopeSharedPtr scope) : scope_(std::move(scope)) {} - - // When the request is destroyed, we need to subtract the value from the gauge. - // We need to look up the gauge again in the scope because it might have been evicted. - // The gauge object itself is kept alive by the shared_ptr in the state, so we can access its - // name and tags to re-lookup/re-create it in the scope. - ~AccessLogState() override { - for (const auto& [gauge_ptr, state] : inflight_gauges_) { - // TODO(taoxuy): make this as an accessor of the - // Stat class. - Stats::StatNameTagVector tag_names; - state.gauge_->iterateTagStatNames( - [&tag_names](Stats::StatName name, Stats::StatName value) -> bool { - tag_names.emplace_back(name, value); - return true; - }); - - // Using state.gauge_->statName() directly would be incorrect because it returns the fully - // qualified name (including tags). Passing this full name to scope_->gaugeFromStatName(...) - // would cause the scope to attempt tag extraction on the full name. Since the tags in - // AccessLogState are often dynamic and not configured in the global tag extractors, this - // extraction would likely fail to identify the tags correctly, resulting in a gauge with a - // different identity (the full name as the stat name and no tags). - auto& gauge = scope_->gaugeFromStatNameWithTags( - state.gauge_->tagExtractedStatName(), tag_names, Stats::Gauge::ImportMode::Accumulate); - gauge.sub(state.value_); - } - } - - void addInflightGauge(Stats::Gauge* gauge, uint64_t value) { - inflight_gauges_.try_emplace(gauge, Stats::GaugeSharedPtr(gauge), value); - } - - absl::optional removeInflightGauge(Stats::Gauge* gauge) { - auto it = inflight_gauges_.find(gauge); - if (it == inflight_gauges_.end()) { - return absl::nullopt; - } - uint64_t value = it->second.value_; - inflight_gauges_.erase(it); - return value; - } - - static constexpr absl::string_view key() { return "envoy.access_loggers.stats.access_log_state"; } - -private: - struct State { - State(Stats::GaugeSharedPtr gauge, uint64_t value) : gauge_(std::move(gauge)), value_(value) {} - - Stats::GaugeSharedPtr gauge_; - uint64_t value_; - }; - - Stats::ScopeSharedPtr scope_; - - // The map key holds a raw pointer to the gauge. The value holds a ref-counted pointer to ensure - // the gauge is not destroyed if it is evicted from the stats scope. - absl::flat_hash_map inflight_gauges_; -}; - Formatter::FormatterProviderPtr parseValueFormat(absl::string_view format, const std::vector& commands) { @@ -138,6 +76,91 @@ class TagActionValidationVisitor } // namespace +AccessLogState::~AccessLogState() { + for (const auto& p : inflight_gauges_) { + Stats::Gauge& gauge_stat = parent_->scope().gaugeFromStatNameWithTags( + p.first.statName(), p.first.tags(), p.second.import_mode_); + gauge_stat.sub(p.second.value_); + } +} + +void AccessLogState::addInflightGauge(Stats::StatName stat_name, + Stats::StatNameTagVectorOptConstRef tags, + Stats::Gauge::ImportMode import_mode, uint64_t value, + std::vector tags_storage) { + if (value == 0) { + return; + } + + GaugeKey key{stat_name, tags}; + + auto it = inflight_gauges_.find(key); + if (it == inflight_gauges_.end()) { + key.makeOwned(); + auto [new_it, inserted] = inflight_gauges_.emplace( + std::move(key), InflightGauge{std::move(tags_storage), 0, import_mode}); + it = new_it; + } + it->second.value_ += value; + parent_->scope().gaugeFromStatNameWithTags(stat_name, tags, import_mode).add(value); +} + +void AccessLogState::removeInflightGauge(Stats::StatName stat_name, + Stats::StatNameTagVectorOptConstRef tags, + Stats::Gauge::ImportMode import_mode, uint64_t value) { + if (value == 0) { + return; + } + + GaugeKey key{stat_name, tags}; + + Stats::Gauge& gauge_stat = + parent_->scope().gaugeFromStatNameWithTags(stat_name, tags, import_mode); + + auto it = inflight_gauges_.find(key); + const bool was_found = (it != inflight_gauges_.end()); + if (was_found) { + ENVOY_BUG(it->second.value_ >= value, "Connection gauge underflow in removeInflightGauge"); + it->second.value_ -= value; + gauge_stat.sub(value); + if (it->second.value_ == 0) { + inflight_gauges_.erase(it); + } + } + ASSERT(was_found); +} + +GaugeKey::GaugeKey(Stats::StatName stat_name, Stats::StatNameTagVectorOptConstRef borrowed_tags) + : stat_name_(stat_name), borrowed_tags_(borrowed_tags) {} + +void GaugeKey::makeOwned() { + ASSERT(!(borrowed_tags_.has_value() && owned_tags_.has_value()), + "Both borrowed and owned tags are present in GaugeKey::makeOwned"); + if (borrowed_tags_.has_value() && !owned_tags_.has_value()) { + owned_tags_ = borrowed_tags_.value().get(); + borrowed_tags_ = absl::nullopt; + } +} + +Stats::StatNameTagVectorOptConstRef GaugeKey::tags() const { + if (owned_tags_.has_value()) { + return std::cref(owned_tags_.value()); + } + return borrowed_tags_; +} + +bool GaugeKey::operator==(const GaugeKey& rhs) const { + if (stat_name_ != rhs.stat_name_) { + return false; + } + Stats::StatNameTagVectorOptConstRef lhs_tags = tags(); + Stats::StatNameTagVectorOptConstRef rhs_tags = rhs.tags(); + if (lhs_tags.has_value() != rhs_tags.has_value()) { + return false; + } + return !lhs_tags.has_value() || lhs_tags.value().get() == rhs_tags.value().get(); +} + StatsAccessLog::StatsAccessLog(const envoy::extensions::access_loggers::stats::v3::Config& config, Server::Configuration::GenericFactoryContext& context, AccessLog::FilterPtr&& filter, @@ -417,31 +440,31 @@ void StatsAccessLog::emitLogForGauge(const Gauge& gauge, const Formatter::Contex Stats::Gauge::ImportMode import_mode = op == Gauge::OperationType::SET ? Stats::Gauge::ImportMode::NeverImport : Stats::Gauge::ImportMode::Accumulate; - auto& gauge_stat = scope_->gaugeFromStatNameWithTags(gauge.stat_.name_, tags, import_mode); - if (op == Gauge::OperationType::PAIRED_ADD || op == Gauge::OperationType::PAIRED_SUBTRACT) { + if (op == Gauge::OperationType::SET) { + Stats::Gauge& gauge_stat = + scope_->gaugeFromStatNameWithTags(gauge.stat_.name_, tags, import_mode); + gauge_stat.set(value); + } else if (op == Gauge::OperationType::PAIRED_ADD || + op == Gauge::OperationType::PAIRED_SUBTRACT) { auto& filter_state = const_cast(stream_info.filterState()); if (!filter_state.hasData(AccessLogState::key())) { - filter_state.setData(AccessLogState::key(), std::make_shared(scope_), - StreamInfo::FilterState::StateType::Mutable, - StreamInfo::FilterState::LifeSpan::Request); + // Using LifeSpan::Request binds the state to the duration of the stream (HTTP) or session + // (TCP). For pure TCP connections (L4), the "request" scope corresponds to the connection + // session itself (as there is no multiplexing). When the stream or session terminates, + // FilterState is destroyed, triggering AccessLogState cleanup. This mechanism works uniformly + // whether the access log is configured at the L4 or L7 filter level. + filter_state.setData( + AccessLogState::key(), std::make_shared(shared_from_this()), + StreamInfo::FilterState::StateType::Mutable, StreamInfo::FilterState::LifeSpan::Request); } auto* state = filter_state.getDataMutable(AccessLogState::key()); if (op == Gauge::OperationType::PAIRED_ADD) { - state->addInflightGauge(&gauge_stat, value); - gauge_stat.add(value); + state->addInflightGauge(gauge.stat_.name_, tags, import_mode, value, std::move(storage)); } else { - absl::optional added_value = state->removeInflightGauge(&gauge_stat); - if (added_value.has_value()) { - gauge_stat.sub(added_value.value()); - } + state->removeInflightGauge(gauge.stat_.name_, tags, import_mode, value); } - return; - } - - if (op == Gauge::OperationType::SET) { - gauge_stat.set(value); } } diff --git a/source/extensions/access_loggers/stats/stats.h b/source/extensions/access_loggers/stats/stats.h index 8a584e88b6d62..74ed8f18554cd 100644 --- a/source/extensions/access_loggers/stats/stats.h +++ b/source/extensions/access_loggers/stats/stats.h @@ -4,18 +4,82 @@ #include "envoy/extensions/access_loggers/stats/v3/stats.pb.h" #include "envoy/stats/stats.h" #include "envoy/stats/tag.h" +#include "envoy/stream_info/filter_state.h" #include "source/common/matcher/matcher.h" +#include "source/common/stats/symbol_table.h" #include "source/extensions/access_loggers/common/access_log_base.h" #include "source/extensions/matching/actions/transform_stat/transform_stat.h" +#include "absl/container/node_hash_map.h" + namespace Envoy { namespace Extensions { namespace AccessLoggers { namespace StatsAccessLog { -class StatsAccessLog : public AccessLoggers::Common::ImplBase { +// GaugeKey serves as a lock-free map key composed of exactly the configuration +// properties that define a fully resolved gauge metric. +// +// It preserves the raw components (base name + tags) allowing us to safely +// re-create the gauge from the scope if it gets evicted while the request is in-flight. +// +// To avoid heap-allocating a new std::vector on every map lookup (which happens +// on every single gauge increment/decrement), this key acts as a lightweight +// zero-allocation "view" using `borrowed_tags_` during map lookups. +// When the key actually needs to be safely persisted into the map, `makeOwned()` +// is explicitly called to allocate and copy the tags into `owned_tags_`. +class GaugeKey { +public: + GaugeKey(Stats::StatName stat_name, Stats::StatNameTagVectorOptConstRef borrowed_tags); + + GaugeKey(const GaugeKey&) = delete; + GaugeKey& operator=(const GaugeKey&) = delete; + GaugeKey(GaugeKey&&) = default; + GaugeKey& operator=(GaugeKey&&) = default; + + void makeOwned(); + + Stats::StatNameTagVectorOptConstRef tags() const; + + Stats::StatName statName() const { return stat_name_; } + + bool operator==(const GaugeKey& rhs) const; + + template friend H AbslHashValue(H h, const GaugeKey& key) { + // We hash the logical tag content to match operator== behavior, ignoring + // whether the tags are stored in owned_tags_ or borrowed_tags_. This ensures + // that two equal keys produce the same hash regardless of their storage representation. + Stats::StatNameTagVectorOptConstRef tags = key.tags(); + if (tags.has_value()) { + h = H::combine(std::move(h), key.stat_name_, true); + for (const auto& tag : tags.value().get()) { + h = H::combine(std::move(h), tag.first, tag.second); + } + return h; + } + return H::combine(std::move(h), key.stat_name_, false); + } + +private: + // The backing store for `stat_name_` is the StatNamePool owned by the StatsAccessLog::Config, + // which has the same lifetime as the logger itself. + Stats::StatName stat_name_; + + // The `StatName`s in `owned_tags_` (when present) represent dynamically generated tags. + // Their memory is backed by the Envoy stats store's SymbolTable. To ensure these dynamic tags + // are not freed prematurely and do not leak, their reference counts are kept alive by + // `StatNameDynamicStorage` instances stored alongside the gauge value in `InflightGauge` + // within the `AccessLogState`. + absl::optional owned_tags_; + + Stats::StatNameTagVectorOptConstRef borrowed_tags_{absl::nullopt}; +}; + +class StatsAccessLog : public AccessLoggers::Common::ImplBase, + public std::enable_shared_from_this { public: + Stats::Scope& scope() const { return *scope_; } StatsAccessLog(const envoy::extensions::access_loggers::stats::v3::Config& config, Server::Configuration::GenericFactoryContext& context, AccessLog::FilterPtr&& filter, @@ -102,7 +166,42 @@ class StatsAccessLog : public AccessLoggers::Common::ImplBase { const std::vector gauges_; }; +class AccessLogState : public StreamInfo::FilterState::Object { +public: + AccessLogState(std::shared_ptr parent) : parent_(std::move(parent)) {} + + ~AccessLogState() override; + + // Adds an incremental value to an existing gauge, or creates it if that gauge doesn't exist. + // Zero values are ignored. If the same value isn't removed with `removeInflightGauge`, the + // value is removed when the object is destroyed. + void addInflightGauge(Stats::StatName stat_name, Stats::StatNameTagVectorOptConstRef tags, + Stats::Gauge::ImportMode import_mode, uint64_t value, + std::vector tags_storage); + + // Removes an amount from an existing gauge, allowing the gauge to be evicted if the value reaches + // 0. + void removeInflightGauge(Stats::StatName stat_name, Stats::StatNameTagVectorOptConstRef tags, + Stats::Gauge::ImportMode import_mode, uint64_t value); + + static constexpr absl::string_view key() { return "envoy.access_loggers.stats.access_log_state"; } + +private: + // Hold a shared_ptr to the parent to ensure the parent and its members exist for the lifetime of + // AccessLogState. + std::shared_ptr parent_; + + struct InflightGauge { + std::vector tags_storage_; + uint64_t value_; + Stats::Gauge::ImportMode import_mode_; + }; + + absl::node_hash_map inflight_gauges_; +}; + } // namespace StatsAccessLog + } // namespace AccessLoggers } // namespace Extensions } // namespace Envoy diff --git a/test/common/stats/thread_local_store_test.cc b/test/common/stats/thread_local_store_test.cc index ca73948af9e0b..2be652af8714b 100644 --- a/test/common/stats/thread_local_store_test.cc +++ b/test/common/stats/thread_local_store_test.cc @@ -536,6 +536,7 @@ TEST_F(StatsThreadLocalStoreTest, StatsNumLimitsWithEviction) { store_->mergeHistograms([]() -> void {}); // First eviction marks stats as unused. + g1.sub(1); // Make value 0 so it can be marked unused store_->evictUnused(); EXPECT_FALSE(c1.used()); EXPECT_FALSE(g1.used()); @@ -706,6 +707,7 @@ TEST_F(StatsThreadLocalStoreTest, Eviction) { store_->mergeHistograms([]() -> void {}); // Eviction only marks unused but does not remove the counters. + g1.set(0); // Make value 0 so it can be marked unused store_->evictUnused(); EXPECT_EQ(&c1, &scope->counterFromString("c1")); @@ -716,7 +718,7 @@ TEST_F(StatsThreadLocalStoreTest, Eviction) { EXPECT_EQ(&g1, &scope->gaugeFromString("g1", Gauge::ImportMode::Accumulate)); EXPECT_EQ(&g1, &scope1->gaugeFromString("g1", Gauge::ImportMode::Accumulate)); EXPECT_FALSE(g1.used()); - EXPECT_EQ(5, g1.value()); + EXPECT_EQ(0, g1.value()); EXPECT_EQ(1UL, store_->gauges().size()); EXPECT_EQ(&t1, &scope->textReadoutFromString("t1")); @@ -731,6 +733,8 @@ TEST_F(StatsThreadLocalStoreTest, Eviction) { EXPECT_EQ(1UL, store_->histograms().size()); } + // Gauge value was already made zero above + // Eviction removes here. EXPECT_CALL(tls_, runOnAllThreads(_, _)).Times(testing::AtLeast(1)); store_->evictUnused(); @@ -778,6 +782,7 @@ TEST_F(StatsThreadLocalStoreTest, EvictionGaugesInterleavedOperations) { // 2. MarkUnused / Evict // First pass marks unused. Note that evictUnused() only removes if it was ALREADY unused. // Since we just used it (g1.add(10)), the first call will only mark it as unused. + g1.sub(10); // Make value 0 so it can be marked unused store_->evictUnused(); EXPECT_FALSE(g1.used()); EXPECT_EQ(1UL, store_->gauges().size()); @@ -795,7 +800,7 @@ TEST_F(StatsThreadLocalStoreTest, EvictionGaugesInterleavedOperations) { // 3. Interleaved PAIRED_ADD (add) on the held reference g1_ref->add(5); - EXPECT_EQ(15, g1_ref->value()); + EXPECT_EQ(5, g1_ref->value()); EXPECT_TRUE(g1_ref->used()); // 4. Re-resolve and PAIRED_SUBTRACT (sub) @@ -805,10 +810,10 @@ TEST_F(StatsThreadLocalStoreTest, EvictionGaugesInterleavedOperations) { EXPECT_EQ(g1_ref.get(), &g1_resurrected); // Value should be preserved - EXPECT_EQ(15, g1_resurrected.value()); + EXPECT_EQ(5, g1_resurrected.value()); // Perform subtract - g1_resurrected.sub(15); + g1_resurrected.sub(5); EXPECT_EQ(0, g1_resurrected.value()); tls_.shutdownGlobalThreading(); @@ -816,6 +821,60 @@ TEST_F(StatsThreadLocalStoreTest, EvictionGaugesInterleavedOperations) { tls_.shutdownThread(); } +TEST_F(StatsThreadLocalStoreTest, EvictionGauges) { + InSequence s; + store_->initializeThreading(main_thread_dispatcher_, tls_); + + ScopeSharedPtr scope = store_->rootScope()->createScope("scope.", /*evictable=*/true); + + // 1. Create gauge and add to make it non-zero + Gauge& g1 = scope->gaugeFromString("g1", Gauge::ImportMode::Accumulate); + g1.add(10); + EXPECT_EQ(10, g1.value()); + EXPECT_TRUE(g1.used()); + + // First pass marks unused. Note that evictUnused() only removes if it was ALREADY unused. + store_->evictUnused(); + EXPECT_TRUE(g1.used()); // Value was non-zero, it should stay used. + EXPECT_EQ(1UL, store_->gauges().size()); + + // Second pass would normally evict from scope cache if it was zero, but since it's non-zero, + // it should stay. + store_->evictUnused(); + + // Verify STILL in scope + StatNameManagedStorage g1_name("scope.g1", symbol_table_); + auto found_gauge = scope->findGauge(g1_name.statName()); + ASSERT_TRUE(found_gauge.has_value()); + EXPECT_EQ(&g1, &(found_gauge.value().get())); + + // Verify still in store (allocator) + EXPECT_EQ(1UL, store_->gauges().size()); + + // 2. Now subtract to make it zero and evict + g1.sub(10); + EXPECT_EQ(0, g1.value()); + + // First pass marks unused + store_->evictUnused(); + main_thread_dispatcher_.run(Event::Dispatcher::RunType::NonBlock); + + // Second pass actually evicts it here + EXPECT_CALL(tls_, runOnAllThreads(_, _)).Times(testing::AtLeast(1)); + store_->evictUnused(); + main_thread_dispatcher_.run(Event::Dispatcher::RunType::NonBlock); + + // Verify removed from scope + EXPECT_FALSE(scope->findGauge(g1_name.statName()).has_value()); + + // Verify removed from store + EXPECT_EQ(0UL, store_->gauges().size()); + + tls_.shutdownGlobalThreading(); + store_->shutdownThreading(); + tls_.shutdownThread(); +} + TEST_F(StatsThreadLocalStoreTest, NestedScopes) { InSequence s; store_->initializeThreading(main_thread_dispatcher_, tls_); diff --git a/test/extensions/access_loggers/stats/BUILD b/test/extensions/access_loggers/stats/BUILD index 608bf73abae7b..1000b432e96f6 100644 --- a/test/extensions/access_loggers/stats/BUILD +++ b/test/extensions/access_loggers/stats/BUILD @@ -1,5 +1,7 @@ load( "//bazel:envoy_build_system.bzl", + "envoy_benchmark_test", + "envoy_cc_benchmark_binary", "envoy_package", ) load( @@ -22,9 +24,11 @@ envoy_extension_cc_test( "//source/common/stats:thread_local_store_lib", "//source/extensions/access_loggers/stats:stats_lib", "//source/extensions/matching/actions/transform_stat:config", + "//test/common/memory:memory_test_utility_lib", "//test/mocks/server:factory_context_mocks", "//test/mocks/stream_info:stream_info_mocks", "//test/test_common:logging_lib", + "@abseil-cpp//absl/hash:hash_testing", ], ) @@ -36,9 +40,29 @@ envoy_extension_cc_test( rbe_pool = "6gig", deps = [ "//source/extensions/access_loggers/stats:config", + "//source/extensions/filters/network/tcp_proxy:config", "//source/extensions/matching/actions/transform_stat:config", "//test/integration:http_integration_lib", "//test/test_common:utility_lib", "@envoy_api//envoy/extensions/filters/network/http_connection_manager/v3:pkg_cc_proto", ], ) + +envoy_cc_benchmark_binary( + name = "stats_speed_test", + srcs = ["stats_speed_test.cc"], + rbe_pool = "6gig", + deps = [ + "//source/common/stats:thread_local_store_lib", + "//source/extensions/access_loggers/stats:stats_lib", + "//test/mocks/server:factory_context_mocks", + "//test/mocks/stream_info:stream_info_mocks", + "//test/test_common:utility_lib", + "@benchmark", + ], +) + +envoy_benchmark_test( + name = "stats_speed_test_benchmark_test", + benchmark_binary = "stats_speed_test", +) diff --git a/test/extensions/access_loggers/stats/integration_test.cc b/test/extensions/access_loggers/stats/integration_test.cc index 81b23c73aff9d..c4d418bd60f0d 100644 --- a/test/extensions/access_loggers/stats/integration_test.cc +++ b/test/extensions/access_loggers/stats/integration_test.cc @@ -30,7 +30,7 @@ class StatsAccessLogIntegrationTest : public HttpIntegrationTest, hcm.mutable_access_log_options()->set_flush_access_log_on_new_request(true); } for (const auto& config_yaml : config_yamls) { - auto* access_log = hcm.add_access_log(); + envoy::config::accesslog::v3::AccessLog* access_log = hcm.add_access_log(); TestUtility::loadFromYaml(config_yaml, *access_log); } }); @@ -80,7 +80,7 @@ TEST_P(StatsAccessLogIntegrationTest, Basic) { }; codec_client_ = makeHttpConnection(lookupPort("http")); - auto response = codec_client_->makeHeaderOnlyRequest(request_headers); + IntegrationStreamDecoderPtr response = codec_client_->makeHeaderOnlyRequest(request_headers); ASSERT_TRUE(response->waitForEndStream()); EXPECT_EQ(response->headers().getStatusValue(), "200"); @@ -89,7 +89,8 @@ TEST_P(StatsAccessLogIntegrationTest, Basic) { test_server_->waitForCounterEq("test_stat_prefix.formatcounter", 200); test_server_->waitUntilHistogramHasSamples("test_stat_prefix.testhistogram.tag.mytagvalue"); - auto histogram = test_server_->histogram("test_stat_prefix.testhistogram.tag.mytagvalue"); + Stats::ParentHistogramSharedPtr histogram = + test_server_->histogram("test_stat_prefix.testhistogram.tag.mytagvalue"); EXPECT_EQ(1, TestUtility::readSampleCount(test_server_->server().dispatcher(), *histogram)); EXPECT_EQ(2, static_cast( TestUtility::readSampleSum(test_server_->server().dispatcher(), *histogram))); @@ -164,13 +165,14 @@ TEST_P(StatsAccessLogIntegrationTest, PercentHistogram) { }; codec_client_ = makeHttpConnection(lookupPort("http")); - auto response = codec_client_->makeHeaderOnlyRequest(request_headers); + IntegrationStreamDecoderPtr response = codec_client_->makeHeaderOnlyRequest(request_headers); ASSERT_TRUE(response->waitForEndStream()); EXPECT_EQ(response->headers().getStatusValue(), "200"); test_server_->waitUntilHistogramHasSamples("test_stat_prefix.testhistogram"); - auto histogram = test_server_->histogram("test_stat_prefix.testhistogram"); + Stats::ParentHistogramSharedPtr histogram = + test_server_->histogram("test_stat_prefix.testhistogram"); EXPECT_EQ(1, TestUtility::readSampleCount(test_server_->server().dispatcher(), *histogram)); double p100 = histogram->cumulativeStatistics().computedQuantiles().back(); @@ -204,7 +206,7 @@ TEST_P(StatsAccessLogIntegrationTest, ActiveRequestsGauge) { }; codec_client_ = makeHttpConnection(lookupPort("http")); - auto response = codec_client_->makeHeaderOnlyRequest(request_headers); + IntegrationStreamDecoderPtr response = codec_client_->makeHeaderOnlyRequest(request_headers); // Wait for upstream to receive request. waitForNextUpstreamRequest(); @@ -222,6 +224,8 @@ TEST_P(StatsAccessLogIntegrationTest, ActiveRequestsGauge) { // After DownstreamEnd is logged, gauge should be 0. test_server_->waitForGaugeEq("test_stat_prefix.active_requests.request_header_tag.my-tag", 0); + + codec_client_->close(); } TEST_P(StatsAccessLogIntegrationTest, SubtractWithoutAdd) { @@ -245,39 +249,322 @@ TEST_P(StatsAccessLogIntegrationTest, SubtractWithoutAdd) { sub_log_type: DownstreamEnd )EOF"; - init(config_yaml, /*autonomous_upstream=*/false, - /*flush_access_log_on_new_request=*/true); - Http::TestRequestHeaderMapImpl request_headers{ {":method", "GET"}, {":authority", "envoyproxy.io"}, {":path", "/"}, {":scheme", "http"}, {"tag-value", "my-tag"}, }; - codec_client_ = makeHttpConnection(lookupPort("http")); - auto response = codec_client_->makeHeaderOnlyRequest(request_headers); + Http::TestResponseHeaderMapImpl response_headers{{":status", "200"}}; - // Wait for upstream to receive request. - waitForNextUpstreamRequest(); + // In debug mode, this should assert because the subtraction is attempted for a gauge that wasn't + // added and DownstreamEnd evaluates access logs upon stream destruction. We wrap the entire + // connection flow in the death test so the parent process doesn't create a mock connection that + // would crash during test teardown. + EXPECT_DEBUG_DEATH( + { + init(config_yaml, /*autonomous_upstream=*/false, + /*flush_access_log_on_new_request=*/true); + + codec_client_ = makeHttpConnection(lookupPort("http")); + IntegrationStreamDecoderPtr response = + codec_client_->makeHeaderOnlyRequest(request_headers); + + waitForNextUpstreamRequest(); + + // Note: waitForGaugeEq waits for the gauge to exist and equal the value. + // If no stats are emitted yet, it might timeout or fail depending on implementation. + // However, in this case, we expect NO stats to be emitted at start. + // We can't verify "stat doesn't exist" easily with waitForGaugeEq. + // But we proceed. + + upstream_request_->encodeHeaders(response_headers, true); + ASSERT_TRUE(response->waitForEndStream()); + EXPECT_EQ(response->headers().getStatusValue(), "200"); + + test_server_->waitForGaugeEq("test_stat_prefix.active_requests.request_header_tag.my-tag", + 0); + codec_client_->close(); + test_server_->waitForCounterGe("http.config_test.downstream_cx_destroy", 1); + }, + "assert failure: was_found"); +} - // Since DownstreamStart is filtered out, gauge should be 0. - // Note: waitForGaugeEq waits for the gauge to exist and equal the value. - // If no stats are emitted yet, it might timeout or fail depending on implementation. - // However, in this case, we expect NO stats to be emitted at start. - // We can't verify "stat doesn't exist" easily with waitForGaugeEq. - // But we proceed. +TEST_P(StatsAccessLogIntegrationTest, GaugeInterleavedOpsWithEviction) { + const std::string config_yaml = R"( + name: envoy.access_loggers.stats + typed_config: + "@type": type.googleapis.com/envoy.extensions.access_loggers.stats.v3.Config + stat_prefix: test_stat_prefix + gauges: + - stat: + name: active_requests + tags: + - name: request_header_tag + value_format: '%REQUEST_HEADER(tag-value)%' + value_fixed: 1 + add_subtract: + add_log_type: DownstreamStart + sub_log_type: DownstreamEnd +)"; - // Send response from upstream. + init(config_yaml, /*autonomous_upstream=*/false, + /*flush_access_log_on_new_request=*/true); + + Http::TestRequestHeaderMapImpl request_headers{ + {":method", "GET"}, {":authority", "envoyproxy.io"}, {":path", "/"}, + {":scheme", "http"}, {"tag-value", "my-eviction-test-tag"}, + }; + + // Request 1: starts gauge at 1. + IntegrationCodecClientPtr codec_client1 = makeHttpConnection(lookupPort("http")); + IntegrationStreamDecoderPtr response1 = codec_client1->makeHeaderOnlyRequest(request_headers); + waitForNextUpstreamRequest(); + test_server_->waitForGaugeEq( + "test_stat_prefix.active_requests.request_header_tag.my-eviction-test-tag", 1); + + // Simulate eviction from the store. + absl::Notification evict_done; + test_server_->server().dispatcher().post([this, &evict_done]() { + // Two calls are required: the first to mark the stat as unused, and the second to actually + // evict it from the store. + test_server_->statStore().evictUnused(); + test_server_->statStore().evictUnused(); + evict_done.Notify(); + }); + evict_done.WaitForNotification(); + + // Request 2: starts another concurrent request using the same tag. + IntegrationCodecClientPtr codec_client2 = makeHttpConnection(lookupPort("http")); + IntegrationStreamDecoderPtr response2 = codec_client2->makeHeaderOnlyRequest(request_headers); + + // Wait for the second request to reach upstream. + // We need to keep track of the second upstream request. + FakeStreamPtr upstream_request2; + FakeHttpConnectionPtr fake_upstream_connection2; + ASSERT_TRUE(fake_upstreams_[0]->waitForHttpConnection(*dispatcher_, fake_upstream_connection2)); + ASSERT_TRUE(fake_upstream_connection2->waitForNewStream(*dispatcher_, upstream_request2)); + ASSERT_TRUE(upstream_request2->waitForEndStream(*dispatcher_)); + + // The gauge should be kept even with eviction happened and the active request is 2. + test_server_->waitForGaugeEq( + "test_stat_prefix.active_requests.request_header_tag.my-eviction-test-tag", 2); + + // Clean up. Http::TestResponseHeaderMapImpl response_headers{{":status", "200"}}; upstream_request_->encodeHeaders(response_headers, true); + ASSERT_TRUE(response1->waitForEndStream()); + test_server_->waitForGaugeEq( + "test_stat_prefix.active_requests.request_header_tag.my-eviction-test-tag", 1); + upstream_request2->encodeHeaders(response_headers, true); + ASSERT_TRUE(response2->waitForEndStream()); + + // Transition the state from used to unused, but not evicted. + absl::Notification evict_done3; + test_server_->server().dispatcher().post([this, &evict_done3]() { + // Transition the state from used to unused, but not evicted yet. + test_server_->statStore().evictUnused(); + evict_done3.Notify(); + }); + evict_done3.WaitForNotification(); + + test_server_->waitForGaugeEq( + "test_stat_prefix.active_requests.request_header_tag.my-eviction-test-tag", 0); + + codec_client1->close(); + codec_client2->close(); +} - // Wait for client to receive response. +// This test verifies that if the gauge is evicted while the request is in-flight, +// the access logger can successfully recreate it when the request ends. +// In reality, it shouldn't happen because the gauge is protected from eviction while +// in-flight(value > 0). +TEST_P(StatsAccessLogIntegrationTest, ActiveRequestsGaugeEvictedWhileInflight) { + const std::string config_yaml = R"( + name: envoy.access_loggers.stats + typed_config: + "@type": type.googleapis.com/envoy.extensions.access_loggers.stats.v3.Config + stat_prefix: test_stat_prefix + gauges: + - stat: + name: active_requests + tags: + - name: request_header_tag + value_format: '%REQUEST_HEADER(tag-value)%' + value_fixed: 1 + add_subtract: + add_log_type: DownstreamStart + sub_log_type: DownstreamEnd +)"; + + Http::TestRequestHeaderMapImpl request_headers{ + {":method", "GET"}, {":authority", "envoyproxy.io"}, {":path", "/"}, + {":scheme", "http"}, {"tag-value", "my-evict-crash-tag"}, + }; + + Http::TestResponseHeaderMapImpl response_headers{{":status", "200"}}; + + // When the gauge is evicted after ADD but before SUB, the access logger can successfully recreate + // it when the request ends. A newly recreated gauge starts at 0, so subtracting from it causes a + // subtraction underflow warning which is expected to trigger EXPECT_DEBUG_DEATH. + // Note: `EXPECT_DEBUG_DEATH` forks a subprocess. Forked processes do not inherit background + // threads. Since Envoy integration tests rely on background server threads (started by `init`), + // the setup must happen *inside* the block so that the threads are created within the subprocess. + EXPECT_DEBUG_DEATH( + { + init(config_yaml, /*autonomous_upstream=*/false, + /*flush_access_log_on_new_request=*/true); + + // Start request. + IntegrationCodecClientPtr codec_client1 = makeHttpConnection(lookupPort("http")); + IntegrationStreamDecoderPtr response1 = + codec_client1->makeHeaderOnlyRequest(request_headers); + waitForNextUpstreamRequest(); + test_server_->waitForGaugeEq( + "test_stat_prefix.active_requests.request_header_tag.my-evict-crash-tag", 1); + + // Force gauge value to 0 so it can be evicted while FilterState is holding it. + test_server_ + ->gauge("test_stat_prefix.active_requests.request_header_tag.my-evict-crash-tag") + ->set(0); + + // Simulate eviction from the store. + absl::Notification evict_done; + test_server_->server().dispatcher().post([this, &evict_done]() { + // Two calls are required: the first to mark the stat as unused, and the second to + // actually evict it from the store. + test_server_->statStore().evictUnused(); + test_server_->statStore().evictUnused(); + evict_done.Notify(); + }); + evict_done.WaitForNotification(); + + upstream_request_->encodeHeaders(response_headers, true); + ASSERT_TRUE(response1->waitForEndStream()); + + codec_client1->close(); + }, + // This text check ensures the crash is from the underflow assert, not due to + // crashing because of bad stat access in the StatsAccessLog. This text check is the entire + // point of the test. + "child_value_ >= amount"); +} + +TEST_P(StatsAccessLogIntegrationTest, GaugeCleanupOnDestructor) { + const std::string config_yaml = R"( + name: envoy.access_loggers.stats + filter: + log_type_filter: + types: [DownstreamStart] + typed_config: + "@type": type.googleapis.com/envoy.extensions.access_loggers.stats.v3.Config + stat_prefix: test_stat_prefix + gauges: + - stat: + name: active_requests + tags: + - name: request_header_tag + value_format: '%REQUEST_HEADER(tag-value)%' + value_fixed: 1 + add_subtract: + add_log_type: DownstreamStart + sub_log_type: DownstreamEnd +)"; + + init(config_yaml, /*autonomous_upstream=*/false, + /*flush_access_log_on_new_request=*/true); + + Http::TestRequestHeaderMapImpl request_headers{ + {":method", "GET"}, {":authority", "envoyproxy.io"}, {":path", "/"}, + {":scheme", "http"}, {"tag-value", "my-evict-cleanup-tag"}, + }; + + Http::TestResponseHeaderMapImpl response_headers{{":status", "200"}}; + + IntegrationCodecClientPtr codec_client = makeHttpConnection(lookupPort("http")); + IntegrationStreamDecoderPtr response = codec_client->makeHeaderOnlyRequest(request_headers); + waitForNextUpstreamRequest(); + + // DownstreamStart logged, gauge should be 1. + test_server_->waitForGaugeEq( + "test_stat_prefix.active_requests.request_header_tag.my-evict-cleanup-tag", 1); + + upstream_request_->encodeHeaders(response_headers, true); ASSERT_TRUE(response->waitForEndStream()); - EXPECT_EQ(response->headers().getStatusValue(), "200"); - // After DownstreamEnd is logged, subtract should be skipped because Add didn't happen. - // Gauge should still be 0. - test_server_->waitForGaugeEq("test_stat_prefix.active_requests.request_header_tag.my-tag", 0); + codec_client->close(); + + // Since DownstreamEnd is filtered out, the explicit SUB op is skipped. + // When the request dies, AccessLogState destructor should run and subtract the gauge. + // The gauge should go back to 0. + test_server_->waitForGaugeEq( + "test_stat_prefix.active_requests.request_header_tag.my-evict-cleanup-tag", 0); } } // namespace + +class StatsAccessLogTcpIntegrationTest : public testing::TestWithParam, + public BaseIntegrationTest { +public: + StatsAccessLogTcpIntegrationTest() + : BaseIntegrationTest(GetParam(), ConfigHelper::tcpProxyConfig()) {} +}; + +TEST_P(StatsAccessLogTcpIntegrationTest, ActiveTcpConnectionsGauge) { + config_helper_.addConfigModifier([](envoy::config::bootstrap::v3::Bootstrap& bootstrap) { + auto* listener = bootstrap.mutable_static_resources()->mutable_listeners(0); + auto* filter_chain = listener->mutable_filter_chains(0); + auto* filter = filter_chain->mutable_filters(0); + + const std::string tcp_proxy_config_with_access_log = R"EOF( +name: envoy.filters.network.tcp_proxy +typed_config: + "@type": type.googleapis.com/envoy.extensions.filters.network.tcp_proxy.v3.TcpProxy + stat_prefix: tcp_stats + cluster: cluster_0 + access_log_options: + flush_access_log_on_start: true + access_log: + - name: envoy.access_loggers.stats + typed_config: + "@type": type.googleapis.com/envoy.extensions.access_loggers.stats.v3.Config + stat_prefix: test_stat_prefix + gauges: + - stat: + name: active_connections + value_fixed: 1 + add_subtract: + add_log_type: TcpConnectionStart + sub_log_type: TcpConnectionEnd +)EOF"; + + TestUtility::loadFromYaml(tcp_proxy_config_with_access_log, *filter); + }); + + initialize(); + + IntegrationTcpClientPtr client1 = makeTcpConnection(lookupPort("listener_0")); + FakeRawConnectionPtr raw_conn1; + ASSERT_TRUE(fake_upstreams_[0]->waitForRawConnection(raw_conn1)); + ASSERT_TRUE(client1->connected()); + + test_server_->waitForGaugeEq("test_stat_prefix.active_connections", 1); + + IntegrationTcpClientPtr client2 = makeTcpConnection(lookupPort("listener_0")); + FakeRawConnectionPtr raw_conn2; + ASSERT_TRUE(fake_upstreams_[0]->waitForRawConnection(raw_conn2)); + ASSERT_TRUE(client2->connected()); + + test_server_->waitForGaugeEq("test_stat_prefix.active_connections", 2); + + client1->close(); + test_server_->waitForGaugeEq("test_stat_prefix.active_connections", 1); + + client2->close(); + test_server_->waitForGaugeEq("test_stat_prefix.active_connections", 0); +} + +INSTANTIATE_TEST_SUITE_P(IpVersions, StatsAccessLogTcpIntegrationTest, + testing::ValuesIn(TestEnvironment::getIpVersionsForTest()), + TestUtility::ipTestParamsToString); + } // namespace Envoy diff --git a/test/extensions/access_loggers/stats/stats_speed_test.cc b/test/extensions/access_loggers/stats/stats_speed_test.cc new file mode 100644 index 0000000000000..b39bb19f5da70 --- /dev/null +++ b/test/extensions/access_loggers/stats/stats_speed_test.cc @@ -0,0 +1,51 @@ +#include "source/common/stats/allocator_impl.h" +#include "source/common/stats/symbol_table.h" +#include "source/common/stats/thread_local_store.h" +#include "source/extensions/access_loggers/stats/stats.h" + +#include "test/mocks/server/factory_context.h" +#include "test/mocks/stream_info/mocks.h" +#include "test/test_common/utility.h" + +#include "benchmark/benchmark.h" + +using testing::NiceMock; + +namespace Envoy { +namespace Extensions { +namespace AccessLoggers { +namespace StatsAccessLog { + +static void BM_StatsAccessLogAddSubtractGaugeWithTags(benchmark::State& state) { + NiceMock context; + Stats::SymbolTableImpl symbol_table; + Stats::AllocatorImpl alloc(symbol_table); + Stats::ThreadLocalStoreImpl store(alloc); + Stats::StatNamePool pool(store.symbolTable()); + + ON_CALL(context, statsScope()).WillByDefault(testing::ReturnRef(*store.rootScope())); + + envoy::extensions::access_loggers::stats::v3::Config config; + AccessLog::FilterPtr filter = nullptr; + auto logger = std::make_shared(config, context, std::move(filter), + std::vector()); + auto access_log_state = std::make_shared(logger); + + Stats::StatName stat_name = pool.add("test_gauge"); + Stats::StatNameTagVector tags; + tags.emplace_back(pool.add("tag_key_1"), pool.add("tag_value_1")); + tags.emplace_back(pool.add("tag_key_2"), pool.add("tag_value_2")); + tags.emplace_back(pool.add("tag_key_3"), pool.add("tag_value_3")); + + for (auto _ : state) { // NOLINT + access_log_state->addInflightGauge(stat_name, tags, Stats::Gauge::ImportMode::Accumulate, 1, + {}); + access_log_state->removeInflightGauge(stat_name, tags, Stats::Gauge::ImportMode::Accumulate, 1); + } +} +BENCHMARK(BM_StatsAccessLogAddSubtractGaugeWithTags); + +} // namespace StatsAccessLog +} // namespace AccessLoggers +} // namespace Extensions +} // namespace Envoy diff --git a/test/extensions/access_loggers/stats/stats_test.cc b/test/extensions/access_loggers/stats/stats_test.cc index dffb67c0b576e..9361f20e02951 100644 --- a/test/extensions/access_loggers/stats/stats_test.cc +++ b/test/extensions/access_loggers/stats/stats_test.cc @@ -4,6 +4,7 @@ #include "source/common/stats/thread_local_store.h" #include "source/extensions/access_loggers/stats/stats.h" +#include "test/common/memory/memory_test_utility.h" #include "test/mocks/event/mocks.h" #include "test/mocks/server/factory_context.h" #include "test/mocks/server/server_factory_context.h" @@ -13,6 +14,7 @@ #include "test/test_common/logging.h" #include "test/test_common/utility.h" +#include "absl/hash/hash_testing.h" #include "gmock/gmock.h" #include "gtest/gtest.h" @@ -104,6 +106,10 @@ class StatsAccessLoggerTest : public testing::Test { void initialize(const envoy::extensions::access_loggers::stats::v3::Config& config) { auto* gauge = new NiceMock(); gauge_ = gauge; + // Arbitrary non-zero value to represent an active gauge. + ON_CALL(*gauge_, value()).WillByDefault(testing::Return(10)); + // Prevent eviction. + ON_CALL(*gauge_, used()).WillByDefault(testing::Return(true)); gauge_ptr_ = Stats::GaugeSharedPtr(gauge_); gauge_->name_ = "gauge"; gauge_->setTagExtractedName("gauge"); @@ -135,7 +141,7 @@ class StatsAccessLoggerTest : public testing::Test { return scope_; })); - logger_ = std::make_unique(config, context_, std::move(filter_), + logger_ = std::make_shared(config, context_, std::move(filter_), std::vector{}); } @@ -144,7 +150,7 @@ class StatsAccessLoggerTest : public testing::Test { NiceMock context_; std::shared_ptr scope_; std::unique_ptr scope_name_storage_; - std::unique_ptr logger_; + std::shared_ptr logger_; Formatter::Context formatter_context_; NiceMock stream_info_; Stats::GaugeSharedPtr gauge_ptr_; @@ -572,38 +578,94 @@ TEST_F(StatsAccessLoggerTest, GaugeAddSubtractBehavior) { testing::Mock::VerifyAndClearExpectations(&store_); testing::Mock::VerifyAndClearExpectations(&*gauge_); - // Case 2: AccessLogType matches subtract_at but no prior add -> no change - formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); - EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)); - EXPECT_CALL(*gauge_, add(_)).Times(0); - EXPECT_CALL(*gauge_, sub(_)).Times(0); - logger_->log(formatter_context_, stream_info_); - testing::Mock::VerifyAndClearExpectations(&store_); - testing::Mock::VerifyAndClearExpectations(&*gauge_); - - // Case 3: AccessLogType matches add_at -> add + // Case 2: AccessLogType matches add_at -> add formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamStart); - EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)).Times(testing::AtLeast(1)); EXPECT_CALL(*gauge_, add(1)); logger_->log(formatter_context_, stream_info_); testing::Mock::VerifyAndClearExpectations(&store_); testing::Mock::VerifyAndClearExpectations(&*gauge_); - // Case 4: AccessLogType matches subtract_at after add -> subtract + // Case 3: AccessLogType matches subtract_at after add -> subtract formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); - EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)).Times(testing::AtLeast(1)); EXPECT_CALL(*gauge_, sub(1)); logger_->log(formatter_context_, stream_info_); testing::Mock::VerifyAndClearExpectations(&store_); testing::Mock::VerifyAndClearExpectations(&*gauge_); +} + +TEST_F(StatsAccessLoggerTest, GaugeAddZeroValue) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + value_fixed: 0 + add_subtract: + add_log_type: DownstreamStart + sub_log_type: DownstreamEnd +)EOF"; + initialize(yaml); + + // Trigger ADD with value 0 + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamStart); - // Case 5: AccessLogType matches subtract_at again -> no change (already removed from inflight) + // The first time it gets the gauge and calls add(0). + // We don't expect it to actually be added to inflight_gauges_. + EXPECT_CALL(store_, gauge(_, _)).WillRepeatedly(testing::ReturnRef(*gauge_)); + + EXPECT_CALL(*gauge_, add(0)).Times(0); // addInflightGauge skips if value == 0 + logger_->log(formatter_context_, stream_info_); + + // Trigger SUBTRACT formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); - EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)); - EXPECT_CALL(*gauge_, sub(1)).Times(0); + // We expect no `sub(0)` interaction here because it wasn't added to inflight_gauges_. + EXPECT_CALL(*gauge_, sub(_)).Times(0); logger_->log(formatter_context_, stream_info_); } +TEST_F(StatsAccessLoggerTest, GaugeSubtractBeforeAdd) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + value_fixed: 1 + add_subtract: + add_log_type: DownstreamStart + sub_log_type: DownstreamEnd +)EOF"; + initialize(yaml); + + // Subtract without add -> crashes in debug mode due to missing inflight gauge, but passes in + // production since it's the last step + EXPECT_DEBUG_DEATH( + { + formatter_context_.setAccessLogType( + envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)) + .Times(testing::AtLeast(1)); + EXPECT_CALL(*gauge_, add(_)).Times(0); + EXPECT_CALL(*gauge_, sub(_)).Times(0); + logger_->log(formatter_context_, stream_info_); + }, + "assert failure: was_found"); + + // Case 4: Subtracting a gauge that was already removed -> crashes in debug mode due to missing + // inflight gauge, but passes in production + EXPECT_DEBUG_DEATH( + { + formatter_context_.setAccessLogType( + envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)) + .Times(testing::AtLeast(1)); + EXPECT_CALL(*gauge_, sub(_)).Times(0); + logger_->log(formatter_context_, stream_info_); + }, + "assert failure: was_found"); +} + TEST_F(StatsAccessLoggerTest, PairedSubtractIgnoresConfiguredValue) { const std::string yaml = R"EOF( stat_prefix: test_stat_prefix @@ -619,13 +681,13 @@ TEST_F(StatsAccessLoggerTest, PairedSubtractIgnoresConfiguredValue) { // Trigger ADD with value 10 formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamStart); - EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)).Times(testing::AtLeast(1)); EXPECT_CALL(*gauge_, add(10)); logger_->log(formatter_context_, stream_info_); // Trigger SUBTRACT. Should still subtract 10. formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); - EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)).Times(testing::AtLeast(1)); EXPECT_CALL(*gauge_, sub(10)); logger_->log(formatter_context_, stream_info_); } @@ -648,18 +710,21 @@ TEST_F(StatsAccessLoggerTest, DestructionSubtractsRemainingValue) { NiceMock local_stream_info; - // Called once on log() and once on destruction. - EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)).Times(2); + // Called once on log(). + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)).Times(testing::AtLeast(1)); EXPECT_CALL(*gauge_, add(10)); logger_->log(formatter_context_, local_stream_info); // Expect subtraction on destruction EXPECT_CALL(*gauge_, sub(10)); + // Destroy logger before stream_info to simulate logger config deletion while stream is active + logger_.reset(); + // local_stream_info goes out of scope here. } -TEST_F(StatsAccessLoggerTest, AccessLogStateDestructorReconstructsGauge) { +TEST_F(StatsAccessLoggerTest, AccessLogStateDestructorSubtractsFromSavedGauge) { const std::string yaml = R"EOF( stat_prefix: test_stat_prefix gauges: @@ -691,49 +756,74 @@ TEST_F(StatsAccessLoggerTest, AccessLogStateDestructorReconstructsGauge) { // Initial lookup and add EXPECT_CALL(*mock_scope, gaugeFromStatNameWithTags(_, _, Stats::Gauge::ImportMode::Accumulate)) - .WillOnce(Invoke([&](const Stats::StatName& name, Stats::StatNameTagVectorOptConstRef tags, - Stats::Gauge::ImportMode) -> Stats::Gauge& { - saved_name = name; - if (tags) { - for (const auto& tag : tags->get()) { - saved_tags_strs.emplace_back(store_.symbolTable().toString(tag.first), - store_.symbolTable().toString(tag.second)); - } - } - EXPECT_FALSE(saved_tags_strs.empty()); - auto* gauge_with_tags = dynamic_cast(gauge_); - EXPECT_TRUE(gauge_with_tags != nullptr); - gauge_with_tags->setTags(tags->get(), store_.symbolTable()); - return *gauge_; - })); + .WillRepeatedly( + Invoke([&](const Stats::StatName& name, Stats::StatNameTagVectorOptConstRef tags, + Stats::Gauge::ImportMode) -> Stats::Gauge& { + saved_name = name; + if (tags) { + for (const auto& tag : tags->get()) { + saved_tags_strs.emplace_back(store_.symbolTable().toString(tag.first), + store_.symbolTable().toString(tag.second)); + } + EXPECT_FALSE(saved_tags_strs.empty()); + auto* gauge_with_tags = dynamic_cast(gauge_); + EXPECT_TRUE(gauge_with_tags != nullptr); + gauge_with_tags->setTags(tags->get(), store_.symbolTable()); + } + return *gauge_; + })); + EXPECT_CALL(*gauge_, add(10)); logger_->log(formatter_context_, local_stream_info); - // Simulate eviction from scope (or just verify lookup happens again) - // The destructor of AccessLogState should call gaugeFromStatNameWithTags again. - EXPECT_CALL(*mock_scope, gaugeFromStatNameWithTags(_, _, Stats::Gauge::ImportMode::Accumulate)) - .WillOnce(Invoke([&](const Stats::StatName& name, Stats::StatNameTagVectorOptConstRef tags, - Stats::Gauge::ImportMode) -> Stats::Gauge& { - EXPECT_EQ(name, saved_name); - EXPECT_TRUE(tags.has_value()); - if (tags) { - const auto& tags_vec = tags->get(); - // Detailed comparison - EXPECT_EQ(tags_vec.size(), 2); - if (tags_vec.size() == 2) { - EXPECT_EQ(store_.symbolTable().toString(tags_vec[0].first), "tag_name"); - EXPECT_EQ(store_.symbolTable().toString(tags_vec[0].second), "200"); - EXPECT_EQ(store_.symbolTable().toString(tags_vec[1].first), "another_tag"); - EXPECT_EQ(store_.symbolTable().toString(tags_vec[1].second), "value_fixed"); - } - } - return *gauge_; - })); + // The destructor of AccessLogState should call sub(10, _) directly on the saved gauge + // This will trigger a second lookup using gaugeFromString (tags == absl::nullopt). EXPECT_CALL(*gauge_, sub(10)); // local_stream_info goes out of scope here, triggering AccessLogState destructor. } +TEST_F(StatsAccessLoggerTest, SameGaugeAddSubtractDefinedTwice) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + value_fixed: 10 + add_subtract: + add_log_type: DownstreamStart + sub_log_type: DownstreamEnd + - stat: + name: gauge + value_fixed: 20 + add_subtract: + add_log_type: TcpUpstreamConnected + sub_log_type: DownstreamEnd +)EOF"; + initialize(yaml); + + // Trigger ADD for the first definition (DownstreamStart) + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamStart); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)).Times(testing::AtLeast(1)); + EXPECT_CALL(*gauge_, add(10)); + logger_->log(formatter_context_, stream_info_); + + // Trigger ADD for the second definition (TcpUpstreamConnected) + formatter_context_.setAccessLogType( + envoy::data::accesslog::v3::AccessLogType::TcpUpstreamConnected); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)).Times(testing::AtLeast(1)); + // The second gauge is added on TcpUpstreamConnected + EXPECT_CALL(*gauge_, add(20)); + logger_->log(formatter_context_, stream_info_); + + // Trigger SUBTRACT for both (DownstreamEnd) + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)).Times(2); + EXPECT_CALL(*gauge_, sub(10)); + EXPECT_CALL(*gauge_, sub(20)); + logger_->log(formatter_context_, stream_info_); +} + TEST_F(StatsAccessLoggerTest, GaugeNotSet) { const std::string yaml = R"EOF( stat_prefix: test_stat_prefix @@ -1128,6 +1218,195 @@ TEST_F(StatsAccessLoggerTest, StatTagFilterUpdateTagOnHistogram) { logger_->log(formatter_context_, stream_info_); } +TEST(GaugeKeyTest, EqualityAndHashing) { + Stats::SymbolTableImpl symbol_table; + Stats::StatNamePool pool(symbol_table); + + using GaugeKey = AccessLoggers::StatsAccessLog::GaugeKey; + + Stats::StatName name1 = pool.add("name1"); + Stats::StatName name2 = pool.add("name2"); + + GaugeKey key1(name1, absl::nullopt); + GaugeKey key2(name1, absl::nullopt); + GaugeKey key3(name2, absl::nullopt); + + // Basic equality + EXPECT_EQ(key1, key2); + EXPECT_NE(key1, key3); + + // Hash equality + EXPECT_EQ(absl::Hash{}(key1), absl::Hash{}(key2)); + EXPECT_NE(absl::Hash{}(key1), absl::Hash{}(key3)); + + // Tags + Stats::StatName tag_n1 = pool.add("tag_n1"); + Stats::StatName tag_v1 = pool.add("tag_v1"); + Stats::StatName tag_v2 = pool.add("tag_v2"); + + Stats::StatNameTagVector tags1 = {{tag_n1, tag_v1}}; + Stats::StatNameTagVector tags2 = {{tag_n1, tag_v2}}; + + GaugeKey key_tags1(name1, std::cref(tags1)); + GaugeKey key_tags2(name1, std::cref(tags1)); + GaugeKey key_tags3(name1, std::cref(tags2)); + + EXPECT_EQ(key_tags1, key_tags2); + EXPECT_NE(key_tags1, key_tags3); + EXPECT_NE(key1, key_tags1); // No tags vs tags + + EXPECT_EQ(absl::Hash{}(key_tags1), absl::Hash{}(key_tags2)); + EXPECT_NE(absl::Hash{}(key_tags1), absl::Hash{}(key_tags3)); + + // Borrowed vs Owned + GaugeKey key_owned(name1, std::cref(tags1)); + key_owned.makeOwned(); + + EXPECT_EQ(key_tags1, key_owned); // Borrowed vs Owned should be equal if content is same // + // Borrowed vs Owned should be equal if content is same +} + +TEST(GaugeKeyTest, VerifyAbslHashCorrectness) { + Stats::SymbolTableImpl symbol_table; + Stats::StatNamePool pool(symbol_table); + + using GaugeKey = AccessLoggers::StatsAccessLog::GaugeKey; + + Stats::StatName name1 = pool.add("name1"); + Stats::StatName name2 = pool.add("name2"); + Stats::StatName tag_n1 = pool.add("tag_n1"); + Stats::StatName tag_v1 = pool.add("tag_v1"); + Stats::StatName tag_v2 = pool.add("tag_v2"); + + Stats::StatNameTagVector tags1 = {{tag_n1, tag_v1}}; + Stats::StatNameTagVector tags2 = {{tag_n1, tag_v2}}; + + GaugeKey key_empty1(name1, absl::nullopt); + GaugeKey key_empty2(name2, absl::nullopt); + + GaugeKey key_borrowed(name1, std::cref(tags1)); + GaugeKey key_owned(name1, std::cref(tags1)); + key_owned.makeOwned(); + + GaugeKey key_tags2(name1, std::cref(tags2)); + + EXPECT_TRUE(absl::VerifyTypeImplementsAbslHashCorrectly( + std::make_tuple(std::move(key_empty1), std::move(key_empty2), std::move(key_borrowed), + std::move(key_owned), std::move(key_tags2)))); +} + +TEST(GaugeKeyTest, ExactMemoryFootprint) { + Stats::SymbolTableImpl symbol_table; + Stats::StatNamePool pool(symbol_table); + + using GaugeKey = AccessLoggers::StatsAccessLog::GaugeKey; + + // Static size check + EXPECT_LE(sizeof(GaugeKey), 64); + + Stats::StatName name = pool.add("test_gauge"); + Stats::StatName tag_n1 = pool.add("tag_n1"); + Stats::StatName tag_v1 = pool.add("tag_v1"); + + Stats::StatNameTagVector tags = {{tag_n1, tag_v1}}; + + // 1. Check memory usage of empty GaugeKey (no heap should be used by GaugeKey itself). + { + Memory::TestUtil::MemoryTest memory_test; + GaugeKey key(name, absl::nullopt); + // GaugeKey on stack, no heap should be allocated. + EXPECT_MEMORY_EQ(memory_test.consumedBytes(), 0); + } + + // 2. Check memory usage of Borrowed tags GaugeKey. + { + Memory::TestUtil::MemoryTest memory_test; + GaugeKey key(name, std::cref(tags)); + // Borrowed tags should NOT cause heap allocation by GaugeKey itself. + EXPECT_MEMORY_EQ(memory_test.consumedBytes(), 0); + } + + // 3. Check memory usage after making it owned. + { + GaugeKey key(name, std::cref(tags)); + + Memory::TestUtil::MemoryTest memory_test; + key.makeOwned(); + + // We expect some non-zero heap allocation for owned tags. + // The exact match depends on platform calibration (canonical release build). + // We use LE to check if it's within bounds. For exactly 1 tag, it should be small. + // Let's verify it exceeds 0 but is less than some reasonable limit (e.g., 64 bytes). + EXPECT_MEMORY_LE(memory_test.consumedBytes(), 64); + } +} + +TEST_F(StatsAccessLoggerTest, AccessLogStateMemoryFootprint) { + initialize(); + auto access_log_state = std::make_shared(logger_); + + // Static size check + EXPECT_LE(sizeof(AccessLogState), 128); + + Stats::StatNamePool pool(store_.symbolTable()); + + Stats::StatName tag_n = pool.add("tag_n"); + Stats::StatName tag_v = pool.add("tag_v"); + + Stats::StatNameTagVector tags = {{tag_n, tag_v}}; + + const int NUM_ITEMS = 10000; + + // Pre-intern names to isolate map insertion overhead from SymbolTable allocation. + std::vector names; + names.reserve(NUM_ITEMS); + for (int i = 0; i < NUM_ITEMS; ++i) { + names.push_back(pool.add("test_gauge_" + std::to_string(i))); + } + + // Use single MemoryTest scope to measure net difference from creation to destruction (Check for + // absolute zero leaks). + { + Memory::TestUtil::MemoryTest memory_test; + auto access_log_state = std::make_shared(logger_); + + // 1. Add multiple items + for (int i = 0; i < NUM_ITEMS; ++i) { + access_log_state->addInflightGauge(names[i], std::cref(tags), + Stats::Gauge::ImportMode::Accumulate, 1, {}); + } + + // Verify it is within bounds (e.g., less than 384 bytes per entry including map overhead). + // Why 384 bytes? + // - Base slot size (GaugeKey 56B + InflightGauge 40B) = 96B. + // - absl::flat_hash_map load factor overhead can push average to about 110B. + // - Just after table doubling, it can peak to about 220B per item. + // - Tag view making owned adds around 16 to 32B per item. + // - Total peak estimate about 252B. 384 gives a generous 1.5x buffer for allocator page + // alignment. + EXPECT_MEMORY_LE(memory_test.consumedBytes(), NUM_ITEMS * 384); + + // 2. Remove all items + for (int i = 0; i < NUM_ITEMS; ++i) { + access_log_state->removeInflightGauge(names[i], std::cref(tags), + Stats::Gauge::ImportMode::Accumulate, 1); + } + + // absl::flat_hash_map is designed to not release its slots after removing entries, + // which is why we check for such a big memory usage here (approximately 1.6 Megabytes for + // 10,000 items). We set a threshold of 2 Megabytes here to account for this capacity and + // allocator page alignment. + EXPECT_LE(static_cast(memory_test.consumedBytes()), 2097152); + + // Destroy the object! This must release the map capacity. + access_log_state.reset(); + + // After destruction, there should be no leaks. We allow 4096 bytes for allocator caches. + // We use EXPECT_LE directly here to bypass the strict EXPECT_GT constraint of EXPECT_MEMORY_LE. + EXPECT_LE(memory_test.consumedBytes(), 4096); + } +} + } // namespace StatsAccessLog } // namespace AccessLoggers } // namespace Extensions diff --git a/tools/spelling/spelling_dictionary.txt b/tools/spelling/spelling_dictionary.txt index 7a8b3bcae11c1..fccd2e29fa81a 100644 --- a/tools/spelling/spelling_dictionary.txt +++ b/tools/spelling/spelling_dictionary.txt @@ -1445,6 +1445,7 @@ submessages subnet subnets suboptimal +subprocess subsecond subseconds subsegment