access_log: formatter for upstream host metadata (envoyproxy#21724)

Part of envoyproxy#20389. Most of the formatters used in header manipulation are also present in substitution access log formatters. However, UPSTREAM_METADATA was not present in access log formatters.

Also, as noted in envoyproxy#17457 all xxxx_METADATA will be eventually replaced my METADATA(xxxx,...) so this PR also extends METADATA formatter.

api changes are trivial and limited to comments.
Risk Level: Low
Testing: Added unit tests.
Docs Changes: Yes.
Release Notes: Yes

Signed-off-by: Christoph Pakulski <[email protected]>

api/envoy/extensions/formatter/metadata/v3/metadata.proto

@@ -20,6 +20,7 @@ option (udpa.annotations.file_status).package_version_status = ACTIVE;
 // * DYNAMIC
 // * CLUSTER
 // * ROUTE
+// * UPSTREAM_HOST
 //
 // See :ref:`here <config_access_log>` for more information on access log configuration.
 
@@ -51,7 +52,8 @@ option (udpa.annotations.file_status).package_version_status = ACTIVE;
 //  .. note::
 //
 //    METADATA(DYNAMIC:NAMESPACE:KEY):Z is equivalent to :ref:`DYNAMIC_METADATA(NAMESPACE:KEY):Z<config_access_log_format_dynamic_metadata>`
-//    METADATA(CLUSTER:NAMESPACE:KEY):Z is equivalent to :ref:`CLUSTER_METADATA(NAMASPACE:KEY):Z<config_access_log_format_cluster_metadata>`
+//    METADATA(CLUSTER:NAMESPACE:KEY):Z is equivalent to :ref:`CLUSTER_METADATA(NAMESPACE:KEY):Z<config_access_log_format_cluster_metadata>`
+//    METADATA(UPSTREAM_HOST:NAMESPACE:KEY):Z is equivalent to :ref:`UPSTREAM_METADATA(NAMESPACE:KEY):Z<config_access_log_format_upstream_host_metadata>`
 
 message Metadata {
 }

changelogs/current.yaml

@@ -193,6 +193,9 @@ removed_config_or_runtime:
     removed ``envoy.restart_features.no_runtime_singleton`` and replaced with ``envoy.restart_features.remove_runtime_singleton``.
 
 new_features:
+- area: access_log
+  change: |
+    added formatters for :ref:`UPSTREAM_METADATA<config_access_log_format_upstream_host_metadata>` and :ref:`METADATA(UPSTREAM_HOST)<envoy_v3_api_msg_extensions.formatter.metadata.v3.Metadata>`.
 - area: access_log
   change: |
     added new access_log command operators to retrieve upstream connection information change: ``%UPSTREAM_PROTOCOL%``, ``%UPSTREAM_PEER_SUBJECT%``, ``%UPSTREAM_PEER_ISSUER%``, ``%UPSTREAM_TLS_SESSION_ID%``, ``%UPSTREAM_TLS_CIPHER%``, ``%UPSTREAM_TLS_VERSION%``, ``%UPSTREAM_PEER_CERT_V_START%``, ``%UPSTREAM_PEER_CERT_V_END%``, ``%UPSTREAM_PEER_CERT%` and ``%UPSTREAM_FILTER_STATE%``.

docs/root/configuration/observability/access_log/usage.rst

@@ -737,6 +737,40 @@ The following command operators are supported:
 
    CLUSTER_METADATA command operator will be deprecated in the future in favor of :ref:`METADATA<envoy_v3_api_msg_extensions.formatter.metadata.v3.Metadata>` operator.
 
+.. _config_access_log_format_upstream_host_metadata:
+
+%UPSTREAM_METADATA(NAMESPACE:KEY*):Z%
+  HTTP/TCP
+    :ref:`Upstream host Metadata <envoy_v3_api_msg_config.core.v3.Metadata>` info,
+    where NAMESPACE is the filter namespace used when setting the metadata, KEY is an optional
+    lookup key in the namespace with the option of specifying nested keys separated by ':',
+    and Z is an optional parameter denoting string truncation up to Z characters long. The data
+    will be logged as a JSON string. For example, for the following upstream host metadata:
+
+    ``com.test.my_filter: {"test_key": "foo", "test_object": {"inner_key": "bar"}}``
+
+    * %UPSTREAM_METADATA(com.test.my_filter)% will log: ``{"test_key": "foo", "test_object": {"inner_key": "bar"}}``
+    * %UPSTREAM_METADATA(com.test.my_filter:test_key)% will log: ``foo``
+    * %UPSTREAM_METADATA(com.test.my_filter:test_object)% will log: ``{"inner_key": "bar"}``
+    * %UPSTREAM_METADATA(com.test.my_filter:test_object:inner_key)% will log: ``bar``
+    * %UPSTREAM_METADATA(com.unknown_filter)% will log: ``-``
+    * %UPSTREAM_METADATA(com.test.my_filter:unknown_key)% will log: ``-``
+    * %UPSTREAM_METADATA(com.test.my_filter):25% will log (truncation at 25 characters): ``{"test_key": "foo", "test``
+
+  UDP/THRIFT
+    Not implemented ("-").
+
+  .. note::
+
+    For typed JSON logs, this operator renders a single value with string, numeric, or boolean type
+    when the referenced key is a simple value. If the referenced key is a struct or list value, a
+    JSON struct or list is rendered. Structs and lists may be nested. In any event, the maximum
+    length is ignored.
+
+  .. note::
+
+   UPSTREAM_METADATA command operator will be deprecated in the future in favor of :ref:`METADATA<envoy_v3_api_msg_extensions.formatter.metadata.v3.Metadata>` operator.
+
 .. _config_access_log_format_filter_state:
 
 %FILTER_STATE(KEY:F):Z%

source/common/formatter/substitution_formatter.cc

@@ -426,6 +426,16 @@ SubstitutionFormatParser::getKnownFormatters() {
            SubstitutionFormatParser::parseSubcommand(format, ':', filter_namespace, path);
            return std::make_unique<ClusterMetadataFormatter>(filter_namespace, path, max_length);
          }}},
+       {"UPSTREAM_METADATA",
+        {CommandSyntaxChecker::PARAMS_REQUIRED,
+         [](const std::string& format, const absl::optional<size_t>& max_length) {
+           std::string filter_namespace;
+           std::vector<std::string> path;
+
+           SubstitutionFormatParser::parseSubcommand(format, ':', filter_namespace, path);
+           return std::make_unique<UpstreamHostMetadataFormatter>(filter_namespace, path,
+                                                                  max_length);
+         }}},
        {"FILTER_STATE",
         {CommandSyntaxChecker::PARAMS_OPTIONAL | CommandSyntaxChecker::LENGTH_ALLOWED,
          [](const std::string& format, const absl::optional<size_t>& max_length) {
@@ -1806,6 +1816,23 @@ ClusterMetadataFormatter::ClusterMetadataFormatter(const std::string& filter_nam
                           return &cluster_info.value()->metadata();
                         }) {}
 
+UpstreamHostMetadataFormatter::UpstreamHostMetadataFormatter(const std::string& filter_namespace,
+                                                             const std::vector<std::string>& path,
+                                                             absl::optional<size_t> max_length)
+    : MetadataFormatter(filter_namespace, path, max_length,
+                        [](const StreamInfo::StreamInfo& stream_info)
+                            -> const envoy::config::core::v3::Metadata* {
+                          if (!stream_info.upstreamInfo().has_value()) {
+                            return nullptr;
+                          }
+                          Upstream::HostDescriptionConstSharedPtr host =
+                              stream_info.upstreamInfo()->upstreamHost();
+                          if (host == nullptr) {
+                            return nullptr;
+                          }
+                          return host->metadata().get();
+                        }) {}
+
 std::unique_ptr<FilterStateFormatter>
 FilterStateFormatter::create(const std::string& format, const absl::optional<size_t>& max_length,
                              bool is_upstream) {

source/common/formatter/substitution_formatter.h

@@ -509,6 +509,16 @@ class ClusterMetadataFormatter : public MetadataFormatter {
                            const std::vector<std::string>& path, absl::optional<size_t> max_length);
 };
 
+/**
+ * FormatterProvider for UpstreamHostMetadata from StreamInfo.
+ */
+class UpstreamHostMetadataFormatter : public MetadataFormatter {
+public:
+  UpstreamHostMetadataFormatter(const std::string& filter_namespace,
+                                const std::vector<std::string>& path,
+                                absl::optional<size_t> max_length);
+};
+
 /**
  * FormatterProvider for FilterState from StreamInfo.
  */

source/extensions/formatter/metadata/metadata.cc

@@ -49,6 +49,12 @@ MetadataFormatterCommandParser::MetadataFormatterCommandParser() {
                                               absl::optional<size_t> max_length) {
     return std::make_unique<RouteMetadataFormatter>(filter_namespace, path, max_length);
   };
+  metadata_formatter_providers_["UPSTREAM_HOST"] = [](const std::string& filter_namespace,
+                                                      const std::vector<std::string>& path,
+                                                      absl::optional<size_t> max_length) {
+    return std::make_unique<::Envoy::Formatter::UpstreamHostMetadataFormatter>(filter_namespace,
+                                                                               path, max_length);
+  };
 }
 
 ::Envoy::Formatter::FormatterProviderPtr

test/common/formatter/substitution_formatter_test.cc

@@ -2943,6 +2943,80 @@ TEST(SubstitutionFormatterTest, StructFormatterClusterMetadataNoClusterInfoTest)
   }
 }
 
+TEST(SubstitutionFormatterTest, StructFormatterUpstreamHostMetadataTest) {
+  NiceMock<StreamInfo::MockStreamInfo> stream_info;
+  Http::TestRequestHeaderMapImpl request_header{{"first", "GET"}, {":path", "/"}};
+  Http::TestResponseHeaderMapImpl response_header{{"second", "PUT"}, {"test", "test"}};
+  Http::TestResponseTrailerMapImpl response_trailer{{"third", "POST"}, {"test-2", "test-2"}};
+  std::string body;
+
+  const auto metadata = std::make_shared<envoy::config::core::v3::Metadata>();
+  populateMetadataTestData(*metadata);
+  // Get pointers to MockUpstreamInfo  and MockHostDescription.
+  std::shared_ptr<StreamInfo::MockUpstreamInfo> mock_upstream_info =
+      std::dynamic_pointer_cast<StreamInfo::MockUpstreamInfo>(stream_info.upstreamInfo());
+  std::shared_ptr<const Upstream::MockHostDescription> mock_host_description =
+      std::dynamic_pointer_cast<const Upstream::MockHostDescription>(
+          mock_upstream_info->upstreamHost());
+  EXPECT_CALL(*mock_host_description, metadata()).WillRepeatedly(Return(metadata));
+
+  absl::node_hash_map<std::string, std::string> expected_json_map = {
+      {"test_key", "test_value"},
+      {"test_obj", "{\"inner_key\":\"inner_value\"}"},
+      {"test_obj.inner_key", "inner_value"},
+      {"test_obj.non_existing_key", "-"},
+  };
+
+  ProtobufWkt::Struct key_mapping;
+  TestUtility::loadFromYaml(R"EOF(
+    test_key: '%UPSTREAM_METADATA(com.test:test_key)%'
+    test_obj: '%UPSTREAM_METADATA(com.test:test_obj)%'
+    test_obj.inner_key: '%UPSTREAM_METADATA(com.test:test_obj:inner_key)%'
+    test_obj.non_existing_key: '%UPSTREAM_METADATA(com.test:test_obj:non_existing_key)%'
+  )EOF",
+                            key_mapping);
+  StructFormatter formatter(key_mapping, false, false);
+
+  verifyStructOutput(
+      formatter.format(request_header, response_header, response_trailer, stream_info, body),
+      expected_json_map);
+}
+
+TEST(SubstitutionFormatterTest, StructFormatterUpstreamHostMetadataNullPtrs) {
+  testing::NiceMock<StreamInfo::MockStreamInfo> stream_info;
+  Http::TestRequestHeaderMapImpl request_header{{"first", "GET"}, {":path", "/"}};
+  Http::TestResponseHeaderMapImpl response_header{{"second", "PUT"}, {"test", "test"}};
+  Http::TestResponseTrailerMapImpl response_trailer{{"third", "POST"}, {"test-2", "test-2"}};
+  std::string body;
+
+  absl::node_hash_map<std::string, std::string> expected_json_map = {{"test_key", "-"}};
+
+  ProtobufWkt::Struct key_mapping;
+  TestUtility::loadFromYaml(R"EOF(
+    test_key: '%UPSTREAM_METADATA(com.test:test_key)%'
+  )EOF",
+                            key_mapping);
+  StructFormatter formatter(key_mapping, false, false);
+
+  // Empty optional (absl::nullopt)
+  {
+    EXPECT_CALL(Const(stream_info), upstreamInfo()).WillOnce(Return(absl::nullopt));
+    verifyStructOutput(
+        formatter.format(request_header, response_header, response_trailer, stream_info, body),
+        expected_json_map);
+    testing::Mock::VerifyAndClearExpectations(&stream_info);
+  }
+  // Empty host description info (nullptr)
+  {
+    std::shared_ptr<StreamInfo::MockUpstreamInfo> mock_upstream_info =
+        std::dynamic_pointer_cast<StreamInfo::MockUpstreamInfo>(stream_info.upstreamInfo());
+    EXPECT_CALL(*mock_upstream_info, upstreamHost()).WillOnce(Return(nullptr));
+    verifyStructOutput(
+        formatter.format(request_header, response_header, response_trailer, stream_info, body),
+        expected_json_map);
+  }
+}
+
 TEST(SubstitutionFormatterTest, StructFormatterFilterStateTest) {
   Http::TestRequestHeaderMapImpl request_headers;
   Http::TestResponseHeaderMapImpl response_headers;

test/extensions/formatter/metadata/metadata_test.cc

@@ -16,12 +16,12 @@ namespace Formatter {
 
 class MetadataFormatterTest : public ::testing::Test {
 public:
-  MetadataFormatterTest() {
+  MetadataFormatterTest() : metadata_(std::make_shared<envoy::config::core::v3::Metadata>()) {
     // Create metadata object with test values.
     ProtobufWkt::Struct struct_obj;
     auto& fields_map = *struct_obj.mutable_fields();
     fields_map["test_key"] = ValueUtil::stringValue("test_value");
-    (*metadata_.mutable_filter_metadata())["metadata.test"] = struct_obj;
+    (*metadata_->mutable_filter_metadata())["metadata.test"] = struct_obj;
   }
 
   // Method creates a yaml config for specific access log METADATA type.
@@ -43,12 +43,12 @@ class MetadataFormatterTest : public ::testing::Test {
   Http::TestRequestHeaderMapImpl request_headers_;
   Http::TestResponseHeaderMapImpl response_headers_;
   Http::TestResponseTrailerMapImpl response_trailers_;
-  StreamInfo::MockStreamInfo stream_info_;
+  testing::NiceMock<StreamInfo::MockStreamInfo> stream_info_;
   std::string body_;
 
   envoy::config::core::v3::SubstitutionFormatString config_;
   NiceMock<Server::Configuration::MockFactoryContext> context_;
-  envoy::config::core::v3::Metadata metadata_;
+  std::shared_ptr<envoy::config::core::v3::Metadata> metadata_;
 };
 
 // Exception should be thrown for tags different than METADATA.
@@ -68,7 +68,7 @@ TEST_F(MetadataFormatterTest, NonExistingMetadataProvider) {
 TEST_F(MetadataFormatterTest, DynamicMetadata) {
   // Make sure that formatter accesses dynamic metadata.
   EXPECT_CALL(testing::Const(stream_info_), dynamicMetadata())
-      .WillRepeatedly(testing::ReturnRef(metadata_));
+      .WillRepeatedly(testing::ReturnRef(*metadata_));
 
   EXPECT_EQ("test_value",
             getTestMetadataFormatter("DYNAMIC")->format(request_headers_, response_headers_,
@@ -83,18 +83,38 @@ TEST_F(MetadataFormatterTest, ClusterMetadata) {
   // Make sure that formatter accesses cluster metadata.
   absl::optional<std::shared_ptr<NiceMock<Upstream::MockClusterInfo>>> cluster =
       std::make_shared<NiceMock<Upstream::MockClusterInfo>>();
-  EXPECT_CALL(**cluster, metadata()).WillRepeatedly(testing::ReturnRef(metadata_));
+  EXPECT_CALL(**cluster, metadata()).WillRepeatedly(testing::ReturnRef(*metadata_));
   EXPECT_CALL(stream_info_, upstreamClusterInfo()).WillRepeatedly(testing::ReturnPointee(cluster));
 
   EXPECT_EQ("test_value",
             getTestMetadataFormatter("CLUSTER")->format(request_headers_, response_headers_,
                                                         response_trailers_, stream_info_, body_));
 }
 
+// Extensive testing of UpstreamHost Metadata formatter is in
+// test/common/formatter/substitution_formatter_test.cc file.
+// Here just make sure that METADATA(UPSTREAM_HOST .... accesses
+// upstream host's's metadata object.
+TEST_F(MetadataFormatterTest, UpstreamHostMetadata) {
+  // Make sure that formatter accesses cluster metadata.
+  // Get pointers to MockUpstreamInfo  and MockHostDescription.
+  std::shared_ptr<StreamInfo::MockUpstreamInfo> mock_upstream_info =
+      std::dynamic_pointer_cast<StreamInfo::MockUpstreamInfo>(stream_info_.upstreamInfo());
+  std::shared_ptr<const Upstream::MockHostDescription> mock_host_description =
+      std::dynamic_pointer_cast<const Upstream::MockHostDescription>(
+          mock_upstream_info->upstreamHost());
+
+  EXPECT_CALL(*mock_host_description, metadata()).WillRepeatedly(testing::Return(metadata_));
+
+  EXPECT_EQ("test_value", getTestMetadataFormatter("UPSTREAM_HOST")
+                              ->format(request_headers_, response_headers_, response_trailers_,
+                                       stream_info_, body_));
+}
+
 // Test that METADATA(ROUTE accesses stream_info's Route.
 TEST_F(MetadataFormatterTest, RouteMetadata) {
   std::shared_ptr<Router::MockRoute> route{new NiceMock<Router::MockRoute>()};
-  EXPECT_CALL(*route, metadata()).WillRepeatedly(testing::ReturnRef(metadata_));
+  EXPECT_CALL(*route, metadata()).WillRepeatedly(testing::ReturnRef(*metadata_));
   EXPECT_CALL(stream_info_, route()).WillRepeatedly(testing::Return(route));
 
   EXPECT_EQ("test_value",