diff --git a/api/envoy/extensions/access_loggers/stats/v3/BUILD b/api/envoy/extensions/access_loggers/stats/v3/BUILD index 8ee554d4d4f25..2867f10b2e4c1 100644 --- a/api/envoy/extensions/access_loggers/stats/v3/BUILD +++ b/api/envoy/extensions/access_loggers/stats/v3/BUILD @@ -6,6 +6,7 @@ licenses(["notice"]) # Apache 2 api_proto_package( deps = [ + "//envoy/data/accesslog/v3:pkg", "@xds//udpa/annotations:pkg", "@xds//xds/annotations/v3:pkg", ], diff --git a/api/envoy/extensions/access_loggers/stats/v3/stats.proto b/api/envoy/extensions/access_loggers/stats/v3/stats.proto index bcb1296c42cb9..00a947ca7c168 100644 --- a/api/envoy/extensions/access_loggers/stats/v3/stats.proto +++ b/api/envoy/extensions/access_loggers/stats/v3/stats.proto @@ -2,6 +2,8 @@ syntax = "proto3"; package envoy.extensions.access_loggers.stats.v3; +import "envoy/data/accesslog/v3/accesslog.proto"; + import "google/protobuf/wrappers.proto"; import "xds/annotations/v3/status.proto"; @@ -27,6 +29,7 @@ option (udpa.annotations.file_status).package_version_status = ACTIVE; // leading to a denial of service in Envoy, or can overwhelm any configured // stat sinks by sending too many unique metrics. +// [#next-free-field: 6] message Config { option (xds.annotations.v3.message_status).work_in_progress = true; @@ -91,6 +94,58 @@ message Config { google.protobuf.UInt64Value value_fixed = 3 [(validate.rules).uint64 = {gt: 0}]; } + // Configuration for a gauge stat. Gauges can be used to add, subtract, or set + // values, and are useful for tracking concurrency or other mutable values + // over time. + // [#next-free-field: 6] + message Gauge { + // The Set operation config. + message Set { + // The access log type to trigger the operation. + data.accesslog.v3.AccessLogType log_type = 1 [(validate.rules).enum = {defined_only: true}]; + } + + // The PairedAddSubtract operation config. + // Usage restrictions: + // + // 1. We only support add first then subtract logic and we rely on the symmetrical log types + // (e.g., DownstreamStart/DownstreamEnd) to increment and decrement the gauge. + // 2. During runtime, sub_log_type will execute if and only if add_log_type operation has + // been done, tracked by inflight counter in filter state. + // 3. If the add_log_type operation was executed, the sub_log_type will happen when the + // stream/connection is closed, even if the configured log type didn't happen. + message PairedAddSubtract { + // The access log type to trigger the add operation. + data.accesslog.v3.AccessLogType add_log_type = 1 + [(validate.rules).enum = {defined_only: true}]; + + // The access log type to trigger the subtract operation. + data.accesslog.v3.AccessLogType sub_log_type = 2 + [(validate.rules).enum = {defined_only: true}]; + } + + // The name and tags of this gauge. + Stat stat = 1 [(validate.rules).message = {required: true}]; + + // The format string for the value of this gauge, using :ref:`command + // operators `. This must evaluate to a + // positive number. + string value_format = 2 + [(validate.rules).string = {prefix: "%" suffix: "%" ignore_empty: true}]; + + // A fixed value to add/subtract/set to this gauge. + // One of ``value_format`` or ``value_fixed`` must be configured. + google.protobuf.UInt64Value value_fixed = 3 [(validate.rules).uint64 = {gt: 0}]; + + // The PairedAddSubtract operation. + // Only one of PairedAddSubtract and Set can be defined. + PairedAddSubtract add_subtract = 4; + + // The Set operation. + // Only one of PairedAddSubtract and Set can be defined. + Set set = 5; + } + // The stat prefix for the generated stats. string stat_prefix = 1 [(validate.rules).string = {min_len: 1}]; @@ -99,4 +154,7 @@ message Config { // The counters this logger will emit. repeated Counter counters = 4; + + // The gauges this logger will emit. + repeated Gauge gauges = 5; } diff --git a/changelogs/current.yaml b/changelogs/current.yaml index 2a41f6a3306dc..d79b523a2c6e4 100644 --- a/changelogs/current.yaml +++ b/changelogs/current.yaml @@ -141,6 +141,9 @@ new_features: - area: mcp_router change: | Added support for MCP logging method ``logging/setLevel``. +- area: access_log + change: | + Supported gauge in the :ref:`stats access logger `. - area: network change: | Added support access logging in network filters like http filters, by allowing network filters to register as access logger diff --git a/source/extensions/access_loggers/stats/BUILD b/source/extensions/access_loggers/stats/BUILD index c9fb829d83218..7f0ee32f9a724 100644 --- a/source/extensions/access_loggers/stats/BUILD +++ b/source/extensions/access_loggers/stats/BUILD @@ -19,6 +19,7 @@ envoy_cc_library( "//source/common/access_log:access_log_lib", "//source/common/formatter:substitution_format_string_lib", "//source/extensions/access_loggers/common:access_log_base", + "@envoy_api//envoy/data/accesslog/v3:pkg_cc_proto", "@envoy_api//envoy/extensions/access_loggers/stats/v3:pkg_cc_proto", ], ) diff --git a/source/extensions/access_loggers/stats/stats.cc b/source/extensions/access_loggers/stats/stats.cc index ed5319659562a..907c26abef23b 100644 --- a/source/extensions/access_loggers/stats/stats.cc +++ b/source/extensions/access_loggers/stats/stats.cc @@ -1,5 +1,9 @@ #include "source/extensions/access_loggers/stats/stats.h" +#include "envoy/data/accesslog/v3/accesslog.pb.h" +#include "envoy/stats/scope.h" +#include "envoy/stream_info/filter_state.h" + #include "source/common/formatter/substitution_formatter.h" namespace Envoy { @@ -8,6 +12,69 @@ namespace AccessLoggers { namespace StatsAccessLog { namespace { + +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) { @@ -46,7 +113,7 @@ StatsAccessLog::StatsAccessLog(const envoy::extensions::access_loggers::stats::v AccessLog::FilterPtr&& filter, const std::vector& commands) : Common::ImplBase(std::move(filter)), - scope_(context.statsScope().createScope(config.stat_prefix(), true /* evictable */)), + scope_(context.statsScope().createScope(config.stat_prefix())), stat_name_pool_(scope_->symbolTable()), histograms_([&]() { std::vector histograms; for (const auto& hist_cfg : config.histograms()) { @@ -76,6 +143,67 @@ StatsAccessLog::StatsAccessLog(const envoy::extensions::access_loggers::stats::v } } return counters; + }()), + gauges_([&]() { + std::vector gauges; + for (const auto& gauge_cfg : config.gauges()) { + if (gauge_cfg.has_add_subtract() && gauge_cfg.has_set()) { + throw EnvoyException( + "Stats logger gauge cannot have both SET and PAIRED_ADD/PAIRED_SUBTRACT " + "operations."); + } + + if (!gauge_cfg.has_add_subtract() && !gauge_cfg.has_set()) { + throw EnvoyException("Stats logger gauge must have at least one operation configured."); + } + + absl::InlinedVector< + std::pair, 2> + operations; + + if (gauge_cfg.has_add_subtract()) { + if (gauge_cfg.add_subtract().add_log_type() == + envoy::data::accesslog::v3::AccessLogType::NotSet || + gauge_cfg.add_subtract().sub_log_type() == + envoy::data::accesslog::v3::AccessLogType::NotSet) { + throw EnvoyException( + "Stats logger gauge add/subtract operation must have a valid log type."); + } + if (gauge_cfg.add_subtract().add_log_type() == + gauge_cfg.add_subtract().sub_log_type()) { + throw EnvoyException( + fmt::format("Duplicate access log type '{}' in gauge operations.", + static_cast(gauge_cfg.add_subtract().add_log_type()))); + } + operations.emplace_back(gauge_cfg.add_subtract().add_log_type(), + Gauge::OperationType::PAIRED_ADD); + operations.emplace_back(gauge_cfg.add_subtract().sub_log_type(), + Gauge::OperationType::PAIRED_SUBTRACT); + } else { + if (gauge_cfg.set().log_type() == envoy::data::accesslog::v3::AccessLogType::NotSet) { + throw EnvoyException("Stats logger gauge set operation must have a valid log type."); + } + operations.emplace_back(gauge_cfg.set().log_type(), Gauge::OperationType::SET); + } + + Gauge& inserted = + gauges.emplace_back(NameAndTags(gauge_cfg.stat(), stat_name_pool_, commands), nullptr, + 0, std::move(operations)); + + if (!gauge_cfg.value_format().empty() && gauge_cfg.has_value_fixed()) { + throw EnvoyException( + "Stats logger cannot have both `value_format` and `value_fixed` configured."); + } + if (!gauge_cfg.value_format().empty()) { + inserted.value_formatter_ = parseValueFormat(gauge_cfg.value_format(), commands); + } else if (gauge_cfg.has_value_fixed()) { + inserted.value_fixed_ = gauge_cfg.value_fixed().value(); + } else { + throw EnvoyException( + "Stats logger gauge must have either `value_format` or `value_fixed`."); + } + } + return gauges; }()) {} StatsAccessLog::NameAndTags::NameAndTags( @@ -182,6 +310,65 @@ void StatsAccessLog::emitLogConst(const Formatter::Context& context, auto& counter_stat = scope_->counterFromStatNameWithTags(counter.stat_.name_, tags); counter_stat.add(value); } + + for (const auto& gauge : gauges_) { + emitLogForGauge(gauge, context, stream_info); + } +} + +void StatsAccessLog::emitLogForGauge(const Gauge& gauge, const Formatter::Context& context, + const StreamInfo::StreamInfo& stream_info) const { + auto it = std::find_if(gauge.operations_.begin(), gauge.operations_.end(), + [&](const auto& op) { return op.first == context.accessLogType(); }); + if (it == gauge.operations_.end()) { + return; + } + + uint64_t value; + if (gauge.value_formatter_ != nullptr) { + absl::optional computed_value_opt = + getFormatValue(*gauge.value_formatter_, context, stream_info, false); + if (!computed_value_opt.has_value()) { + return; + } + + value = *computed_value_opt; + } else { + value = gauge.value_fixed_; + } + + Gauge::OperationType op = it->second; + + auto [tags, storage] = gauge.stat_.tags(context, stream_info, *scope_); + 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) { + 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); + } + auto* state = filter_state.getDataMutable(AccessLogState::key()); + + if (op == Gauge::OperationType::PAIRED_ADD) { + state->addInflightGauge(&gauge_stat, value); + gauge_stat.add(value); + } else { + absl::optional added_value = state->removeInflightGauge(&gauge_stat); + if (added_value.has_value()) { + gauge_stat.sub(added_value.value()); + } + } + return; + } + + if (op == Gauge::OperationType::SET) { + gauge_stat.set(value); + } } } // namespace StatsAccessLog diff --git a/source/extensions/access_loggers/stats/stats.h b/source/extensions/access_loggers/stats/stats.h index 8aef9f4e6c650..b96e25aeb253c 100644 --- a/source/extensions/access_loggers/stats/stats.h +++ b/source/extensions/access_loggers/stats/stats.h @@ -1,5 +1,6 @@ #pragma once +#include "envoy/data/accesslog/v3/accesslog.pb.h" #include "envoy/extensions/access_loggers/stats/v3/stats.pb.h" #include "envoy/stats/tag.h" @@ -65,11 +66,29 @@ class StatsAccessLog : public Common::ImplBase { uint64_t value_fixed_; }; + struct Gauge { + enum class OperationType { + SET, + PAIRED_ADD, + PAIRED_SUBTRACT, + }; + + NameAndTags stat_; + Formatter::FormatterProviderPtr value_formatter_; + uint64_t value_fixed_; + absl::InlinedVector, 2> + operations_; + }; + + void emitLogForGauge(const Gauge& gauge, const Formatter::Context& context, + const StreamInfo::StreamInfo& stream_info) const; + const Stats::ScopeSharedPtr scope_; Stats::StatNamePool stat_name_pool_; const std::vector histograms_; const std::vector counters_; + const std::vector gauges_; }; } // namespace StatsAccessLog diff --git a/test/common/stats/thread_local_store_test.cc b/test/common/stats/thread_local_store_test.cc index 4635854595676..9efc341d577c2 100644 --- a/test/common/stats/thread_local_store_test.cc +++ b/test/common/stats/thread_local_store_test.cc @@ -759,6 +759,63 @@ TEST_F(StatsThreadLocalStoreTest, Eviction) { tls_.shutdownThread(); } +TEST_F(StatsThreadLocalStoreTest, EvictionGaugesInterleavedOperations) { + InSequence s; + store_->initializeThreading(main_thread_dispatcher_, tls_); + + ScopeSharedPtr scope = store_->rootScope()->createScope("scope.", /*evictable=*/true); + + // 1. Create gauge and PAIRED_ADD (add) + Gauge& g1 = scope->gaugeFromString("g1", Gauge::ImportMode::Accumulate); + g1.add(10); + EXPECT_EQ(10, g1.value()); + EXPECT_TRUE(g1.used()); + + // Hold a reference to prevent destruction upon eviction + GaugeSharedPtr g1_ref = TestUtility::findGauge(*store_, "scope.g1"); + ASSERT_NE(g1_ref, nullptr); + + // 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. + store_->evictUnused(); + EXPECT_FALSE(g1.used()); + EXPECT_EQ(1UL, store_->gauges().size()); + + // Second pass evicts from scope cache because it is now unused. + EXPECT_CALL(tls_, runOnAllThreads(_, _)).Times(testing::AtLeast(1)); + store_->evictUnused(); + + // Verify removed from scope + StatNameManagedStorage g1_name("scope.g1", symbol_table_); + EXPECT_FALSE(scope->findGauge(g1_name.statName()).has_value()); + + // Verify still in store (allocator) due to held ref + EXPECT_EQ(1UL, store_->gauges().size()); + + // 3. Interleaved PAIRED_ADD (add) on the held reference + g1_ref->add(5); + EXPECT_EQ(15, g1_ref->value()); + EXPECT_TRUE(g1_ref->used()); + + // 4. Re-resolve and PAIRED_SUBTRACT (sub) + Gauge& g1_resurrected = scope->gaugeFromString("g1", Gauge::ImportMode::Accumulate); + + // Should be the same object + EXPECT_EQ(g1_ref.get(), &g1_resurrected); + + // Value should be preserved + EXPECT_EQ(15, g1_resurrected.value()); + + // Perform subtract + g1_resurrected.sub(15); + EXPECT_EQ(0, g1_resurrected.value()); + + 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 65dca4aa64181..fc7cd485e090a 100644 --- a/test/extensions/access_loggers/stats/BUILD +++ b/test/extensions/access_loggers/stats/BUILD @@ -17,9 +17,12 @@ envoy_extension_cc_test( extension_names = ["envoy.access_loggers.stats"], deps = [ "//source/common/formatter:stream_info_formatter_extension_lib", + "//source/common/stats:allocator_lib", + "//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:logging_lib", ], ) diff --git a/test/extensions/access_loggers/stats/integration_test.cc b/test/extensions/access_loggers/stats/integration_test.cc index 8dd90c006afe3..81b23c73aff9d 100644 --- a/test/extensions/access_loggers/stats/integration_test.cc +++ b/test/extensions/access_loggers/stats/integration_test.cc @@ -13,13 +13,26 @@ class StatsAccessLogIntegrationTest : public HttpIntegrationTest, public: StatsAccessLogIntegrationTest() : HttpIntegrationTest(Http::CodecType::HTTP1, GetParam()) {} - void init(const std::string& config_yaml) { - autonomous_upstream_ = true; + void init(const std::string& config_yaml, bool autonomous_upstream = true, + bool flush_access_log_on_new_request = false) { + init(std::vector{config_yaml}, autonomous_upstream, + flush_access_log_on_new_request); + } + + void init(const std::vector& config_yamls, bool autonomous_upstream = true, + bool flush_access_log_on_new_request = false) { + autonomous_upstream_ = autonomous_upstream; config_helper_.addConfigModifier( - [&](envoy::extensions::filters::network::http_connection_manager::v3::HttpConnectionManager& + [&, config_yamls]( + envoy::extensions::filters::network::http_connection_manager::v3::HttpConnectionManager& hcm) { - auto* access_log = hcm.add_access_log(); - TestUtility::loadFromYaml(config_yaml, *access_log); + if (flush_access_log_on_new_request) { + 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(); + TestUtility::loadFromYaml(config_yaml, *access_log); + } }); HttpIntegrationTest::initialize(); @@ -164,5 +177,107 @@ TEST_P(StatsAccessLogIntegrationTest, PercentHistogram) { EXPECT_NEAR(0.1, p100, 0.05); } +TEST_P(StatsAccessLogIntegrationTest, ActiveRequestsGauge) { + const std::string config_yaml = R"EOF( + 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 +)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); + + // Wait for upstream to receive request. + waitForNextUpstreamRequest(); + + // After DownstreamStart is logged, gauge should be 1. + test_server_->waitForGaugeEq("test_stat_prefix.active_requests.request_header_tag.my-tag", 1); + + // Send response from upstream. + Http::TestResponseHeaderMapImpl response_headers{{":status", "200"}}; + upstream_request_->encodeHeaders(response_headers, true); + + // Wait for client to receive response. + ASSERT_TRUE(response->waitForEndStream()); + EXPECT_EQ(response->headers().getStatusValue(), "200"); + + // After DownstreamEnd is logged, gauge should be 0. + test_server_->waitForGaugeEq("test_stat_prefix.active_requests.request_header_tag.my-tag", 0); +} + +TEST_P(StatsAccessLogIntegrationTest, SubtractWithoutAdd) { + const std::string config_yaml = R"EOF( + name: envoy.access_loggers.stats + filter: + log_type_filter: + types: [DownstreamEnd] + 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 +)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); + + // Wait for upstream to receive request. + waitForNextUpstreamRequest(); + + // 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. + + // Send response from upstream. + Http::TestResponseHeaderMapImpl response_headers{{":status", "200"}}; + upstream_request_->encodeHeaders(response_headers, true); + + // Wait for client to receive response. + 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); +} + } // namespace } // namespace Envoy diff --git a/test/extensions/access_loggers/stats/stats_test.cc b/test/extensions/access_loggers/stats/stats_test.cc index df90cde640515..1b6d903d3abcd 100644 --- a/test/extensions/access_loggers/stats/stats_test.cc +++ b/test/extensions/access_loggers/stats/stats_test.cc @@ -1,7 +1,16 @@ +#include "envoy/stats/sink.h" + +#include "source/common/stats/allocator_impl.h" +#include "source/common/stats/thread_local_store.h" #include "source/extensions/access_loggers/stats/stats.h" +#include "test/mocks/event/mocks.h" #include "test/mocks/server/factory_context.h" +#include "test/mocks/server/server_factory_context.h" +#include "test/mocks/stats/mocks.h" #include "test/mocks/stream_info/mocks.h" +#include "test/mocks/thread_local/mocks.h" +#include "test/test_common/logging.h" #include "test/test_common/utility.h" #include "gmock/gmock.h" @@ -12,6 +21,52 @@ namespace Extensions { namespace AccessLoggers { namespace StatsAccessLog { +class MockScopeWithGauge : public Stats::MockScope { +public: + using Stats::MockScope::MockScope; + + MOCK_METHOD(Stats::Gauge&, gaugeFromStatNameWithTags, + (const Stats::StatName& name, Stats::StatNameTagVectorOptConstRef tags, + Stats::Gauge::ImportMode import_mode), + (override)); +}; + +// MockGaugeWithTags is introduced to support iterateTagStatNames which is used in +// AccessLogState destructor to reconstruct the gauge with tags. +// +// It uses StatNameDynamicStorage to own the storage for tag names and values. +// This is necessary because the tags passed to gaugeFromStatNameWithTags during +// logging are often backed by temporary storage (stack-allocated in emitLogConst) +// which is destroyed after the log call returns. By making a copy into +// tags_storage_, we ensure that iterateTagStatNames returns valid StatNames even +// if called later (e.g. in AccessLogState::~AccessLogState). +class MockGaugeWithTags : public Stats::MockGauge { +public: + using Stats::MockGauge::MockGauge; + + void iterateTagStatNames(const TagStatNameIterFn& fn) const override { + for (const auto& tag : tags_storage_) { + if (!fn(tag.first->statName(), tag.second->statName())) + return; + } + } + + void setTags(const Stats::StatNameTagVector& tags, Stats::SymbolTable& symbol_table) { + tags_storage_.clear(); + tags_storage_.reserve(tags.size()); + for (const auto& tag : tags) { + tags_storage_.emplace_back(std::make_unique( + symbol_table.toString(tag.first), symbol_table), + std::make_unique( + symbol_table.toString(tag.second), symbol_table)); + } + } + + std::vector, + std::unique_ptr>> + tags_storage_; +}; + class StatsAccessLoggerTest : public testing::Test { public: void initialize(std::string config_yaml = {}) { @@ -43,11 +98,29 @@ class StatsAccessLoggerTest : public testing::Test { } void initialize(const envoy::extensions::access_loggers::stats::v3::Config& config) { + auto* gauge = new NiceMock(); + gauge_ = gauge; + gauge_ptr_ = Stats::GaugeSharedPtr(gauge_); + gauge_->name_ = "gauge"; + gauge_->setTagExtractedName("gauge"); + ON_CALL(store_, gauge(_, _)).WillByDefault(testing::ReturnRef(*gauge_)); + ON_CALL(context_, statsScope()).WillByDefault(testing::ReturnRef(store_.mockScope())); EXPECT_CALL(store_.mockScope(), createScope_(_)) .WillOnce(Invoke([this](const std::string& name) { - Stats::StatNameDynamicStorage storage(name, context_.store_.symbolTable()); - scope_ = std::make_shared>(storage.statName(), store_); + scope_name_storage_ = + std::make_unique(name, context_.store_.symbolTable()); + auto scope = std::make_shared>( + scope_name_storage_->statName(), store_); + ON_CALL(*scope, gaugeFromStatNameWithTags(_, _, _)) + .WillByDefault(Invoke( + [scope_ptr = scope.get()](const Stats::StatName& name, + Stats::StatNameTagVectorOptConstRef tags, + Stats::Gauge::ImportMode import_mode) -> Stats::Gauge& { + return scope_ptr->Stats::MockScope::gaugeFromStatNameWithTags(name, tags, + import_mode); + })); + scope_ = scope; return scope_; })); @@ -59,9 +132,12 @@ class StatsAccessLoggerTest : public testing::Test { NiceMock store_; NiceMock context_; std::shared_ptr scope_; + std::unique_ptr scope_name_storage_; std::unique_ptr logger_; Formatter::Context formatter_context_; NiceMock stream_info_; + Stats::GaugeSharedPtr gauge_ptr_; + Stats::MockGauge* gauge_; }; TEST_F(StatsAccessLoggerTest, IncorrectValueFormatter) { @@ -297,6 +373,370 @@ TEST_F(StatsAccessLoggerTest, EmptyTagFormatter) { logger_->log(formatter_context_, stream_info_); } +TEST_F(StatsAccessLoggerTest, GaugeNonNumberValueFormatted) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + value_format: '%RESPONSE_CODE_DETAILS%' + set: + log_type: DownstreamEnd +)EOF"; + + initialize(yaml); + + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); + + absl::optional not_a_number{"hello"}; + EXPECT_CALL(stream_info_, responseCodeDetails()).WillRepeatedly(testing::ReturnRef(not_a_number)); + EXPECT_CALL(store_, gauge(_, _)).Times(0); + // Note: Logging is verified in NonNumberValueFormatted. We skip verification here due to shared + // rate limiting in ENVOY_LOG_PERIODIC_MISC which causes this second test to suppress the log. + logger_->log(formatter_context_, stream_info_); +} + +// Format string resolved to a number string. +TEST_F(StatsAccessLoggerTest, GaugeNumberValueFormatted) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + value_format: '%BYTES_RECEIVED%' + set: + log_type: DownstreamEnd +)EOF"; + + initialize(yaml); + + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); + + EXPECT_CALL(stream_info_, bytesReceived()).WillRepeatedly(testing::Return(42)); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::NeverImport)); + EXPECT_CALL(*gauge_, set(42)); + logger_->log(formatter_context_, stream_info_); +} + +TEST_F(StatsAccessLoggerTest, GaugeValueFixed) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + tags: + - name: mytag + value_format: '%UPSTREAM_CLUSTER%' + - name: other_tag + value_format: '%RESPONSE_CODE%' + value_fixed: 42 + set: + log_type: DownstreamEnd +)EOF"; + + initialize(yaml); + + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); + + absl::optional a_number{"42"}; + EXPECT_CALL(stream_info_, responseCodeDetails()).WillRepeatedly(testing::ReturnRef(a_number)); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::NeverImport)); + EXPECT_CALL(*gauge_, set(42)); + logger_->log(formatter_context_, stream_info_); +} + +TEST_F(StatsAccessLoggerTest, GaugeOperationTypeSet) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + value_fixed: 42 + set: + log_type: DownstreamEnd +)EOF"; + initialize(yaml); + + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); + + absl::optional a_number{"42"}; + EXPECT_CALL(stream_info_, responseCodeDetails()).WillRepeatedly(testing::ReturnRef(a_number)); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::NeverImport)); + EXPECT_CALL(*gauge_, set(42)); + logger_->log(formatter_context_, stream_info_); +} + +TEST_F(StatsAccessLoggerTest, GaugeBothFormatAndFixed) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + value_format: '%BYTES_RECEIVED%' + value_fixed: 1 + set: + log_type: DownstreamEnd +)EOF"; + + EXPECT_THROW_WITH_MESSAGE( + initialize(yaml), EnvoyException, + "Stats logger cannot have both `value_format` and `value_fixed` configured."); +} + +TEST_F(StatsAccessLoggerTest, GaugeNoValueConfig) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + set: + log_type: DownstreamEnd +)EOF"; + EXPECT_THROW_WITH_MESSAGE(initialize(yaml), EnvoyException, + "Stats logger gauge must have either `value_format` or `value_fixed`."); +} + +TEST_F(StatsAccessLoggerTest, GaugeBothSetAndAddSubtract) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + value_fixed: 42 + add_subtract: + add_log_type: DownstreamStart + sub_log_type: DownstreamEnd + set: + log_type: DownstreamEnd +)EOF"; + EXPECT_THROW_WITH_MESSAGE( + initialize(yaml), EnvoyException, + "Stats logger gauge cannot have both SET and PAIRED_ADD/PAIRED_SUBTRACT operations."); +} + +TEST_F(StatsAccessLoggerTest, GaugeMultipleAdd) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + value_fixed: 42 + add_subtract: + add_log_type: DownstreamStart + sub_log_type: DownstreamStart +)EOF"; + EXPECT_THROW_WITH_MESSAGE(initialize(yaml), EnvoyException, + "Duplicate access log type '4' in gauge operations."); +} + +TEST_F(StatsAccessLoggerTest, GaugeNeitherSetNorAddSubtract) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + value_fixed: 42 +)EOF"; + EXPECT_THROW_WITH_MESSAGE(initialize(yaml), EnvoyException, + "Stats logger gauge must have at least one operation configured."); +} + +TEST_F(StatsAccessLoggerTest, GaugeAddSubtractBehavior) { + 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); + + // Case 1: AccessLogType matches neither -> no change + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::NotSet); + EXPECT_CALL(store_, gauge(_, _)).Times(0); + logger_->log(formatter_context_, stream_info_); + 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 + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamStart); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)); + 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 + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)); + EXPECT_CALL(*gauge_, sub(1)); + logger_->log(formatter_context_, stream_info_); + testing::Mock::VerifyAndClearExpectations(&store_); + testing::Mock::VerifyAndClearExpectations(&*gauge_); + + // Case 5: AccessLogType matches subtract_at again -> no change (already removed from inflight) + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamEnd); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)); + EXPECT_CALL(*gauge_, sub(1)).Times(0); + logger_->log(formatter_context_, stream_info_); +} + +TEST_F(StatsAccessLoggerTest, PairedSubtractIgnoresConfiguredValue) { + 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 +)EOF"; + initialize(yaml); + + // Trigger ADD with value 10 + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamStart); + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)); + 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(*gauge_, sub(10)); + logger_->log(formatter_context_, stream_info_); +} + +TEST_F(StatsAccessLoggerTest, DestructionSubtractsRemainingValue) { + 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 +)EOF"; + initialize(yaml); + + // Trigger ADD using a local StreamInfo so we can control its lifetime. + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamStart); + + NiceMock local_stream_info; + + // Called once on log() and once on destruction. + EXPECT_CALL(store_, gauge(_, Stats::Gauge::ImportMode::Accumulate)).Times(2); + EXPECT_CALL(*gauge_, add(10)); + logger_->log(formatter_context_, local_stream_info); + + // Expect subtraction on destruction + EXPECT_CALL(*gauge_, sub(10)); + + // local_stream_info goes out of scope here. +} + +TEST_F(StatsAccessLoggerTest, AccessLogStateDestructorReconstructsGauge) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + tags: + - name: tag_name + value_format: '%RESPONSE_CODE%' + - name: another_tag + value_format: 'value_fixed' + value_fixed: 10 + add_subtract: + add_log_type: DownstreamStart + sub_log_type: DownstreamEnd +)EOF"; + initialize(yaml); + + auto* mock_scope = dynamic_cast(scope_.get()); + ASSERT_TRUE(mock_scope != nullptr); + + formatter_context_.setAccessLogType(envoy::data::accesslog::v3::AccessLogType::DownstreamStart); + + Stats::StatName saved_name; + std::vector> saved_tags_strs; + + NiceMock local_stream_info; + EXPECT_CALL(local_stream_info, responseCode()) + .WillRepeatedly(testing::Return(absl::optional{200})); + + // 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_; + })); + 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_; + })); + EXPECT_CALL(*gauge_, sub(10)); + + // local_stream_info goes out of scope here, triggering AccessLogState destructor. +} + +TEST_F(StatsAccessLoggerTest, GaugeNotSet) { + const std::string yaml = R"EOF( + stat_prefix: test_stat_prefix + gauges: + - stat: + name: gauge + value_fixed: 42 + set: + log_type: NotSet +)EOF"; + EXPECT_THROW_WITH_MESSAGE(initialize(yaml), EnvoyException, + "Stats logger gauge set operation must have a valid log type."); +} + } // namespace StatsAccessLog } // namespace AccessLoggers } // namespace Extensions