istio · howardjohn · Nov 12, 2019 · Nov 11, 2019
diff --git a/api/envoy/config/accesslog/v2/als.proto b/api/envoy/config/accesslog/v2/als.proto
@@ -42,6 +42,7 @@ message TcpGrpcAccessLogConfig {
 }
 
 // Common configuration for gRPC access logs.
+// [#next-free-field: 6]
 message CommonGrpcAccessLogConfig {
   // The friendly name of the access log to be returned in :ref:`StreamAccessLogsMessage.Identifier
   // <envoy_api_msg_service.accesslog.v2.StreamAccessLogsMessage.Identifier>`. This allows the
@@ -60,4 +61,9 @@ message CommonGrpcAccessLogConfig {
   // this limit it hit, or every time flush interval is elapsed, whichever comes first. Setting it
   // to zero effectively disables the batching. Defaults to 16384.
   google.protobuf.UInt32Value buffer_size_bytes = 4;
+
+  // Additional filter state objects to log in :ref:`filter_state_objects
+  // <envoy_api_field_data.accesslog.v2.AccessLogCommon.filter_state_objects>`.
+  // Logger will call `FilterState::Object::serializeAsProto` to serialize the filter state object.
+  repeated string filter_state_objects_to_log = 5;
 }
diff --git a/api/envoy/config/accesslog/v3alpha/als.proto b/api/envoy/config/accesslog/v3alpha/als.proto
@@ -42,6 +42,7 @@ message TcpGrpcAccessLogConfig {
 }
 
 // Common configuration for gRPC access logs.
+// [#next-free-field: 6]
 message CommonGrpcAccessLogConfig {
   // The friendly name of the access log to be returned in :ref:`StreamAccessLogsMessage.Identifier
   // <envoy_api_msg_service.accesslog.v3alpha.StreamAccessLogsMessage.Identifier>`. This allows the
@@ -60,4 +61,9 @@ message CommonGrpcAccessLogConfig {
   // this limit it hit, or every time flush interval is elapsed, whichever comes first. Setting it
   // to zero effectively disables the batching. Defaults to 16384.
   google.protobuf.UInt32Value buffer_size_bytes = 4;
+
+  // Additional filter state objects to log in :ref:`filter_state_objects
+  // <envoy_api_field_data.accesslog.v3alpha.AccessLogCommon.filter_state_objects>`.
+  // Logger will call `FilterState::Object::serializeAsProto` to serialize the filter state object.
+  repeated string filter_state_objects_to_log = 5;
 }
diff --git a/api/envoy/data/accesslog/v2/accesslog.proto b/api/envoy/data/accesslog/v2/accesslog.proto
@@ -9,6 +9,7 @@ option java_package = "io.envoyproxy.envoy.data.accesslog.v2";
 import "envoy/api/v2/core/address.proto";
 import "envoy/api/v2/core/base.proto";
 
+import "google/protobuf/any.proto";
 import "google/protobuf/duration.proto";
 import "google/protobuf/timestamp.proto";
 import "google/protobuf/wrappers.proto";
@@ -66,7 +67,7 @@ message ConnectionProperties {
 }
 
 // Defines fields that are shared by all Envoy access logs.
-// [#next-free-field: 21]
+// [#next-free-field: 22]
 message AccessLogCommon {
   // [#not-implemented-hide:]
   // This field indicates the rate at which this log entry was sampled.
@@ -162,6 +163,11 @@ message AccessLogCommon {
   // received. Note: This is always the physical peer, even if the remote address is inferred from
   // for example the x-forwarder-for header, proxy protocol, etc.
   api.v2.core.Address downstream_direct_remote_address = 20;
+
+  // Map of filter state in stream info that have been configured to be logged. If the filter
+  // state serialized to any message other than `google.protobuf.Any` it will be packed into
+  // `google.protobuf.Any`.
+  map<string, google.protobuf.Any> filter_state_objects = 21;
 }
 
 // Flags indicating occurrences during request/response processing.

diff --git a/api/envoy/data/accesslog/v3alpha/accesslog.proto b/api/envoy/data/accesslog/v3alpha/accesslog.proto
@@ -9,6 +9,7 @@ option java_package = "io.envoyproxy.envoy.data.accesslog.v3alpha";
 import "envoy/api/v3alpha/core/address.proto";
 import "envoy/api/v3alpha/core/base.proto";
 
+import "google/protobuf/any.proto";
 import "google/protobuf/duration.proto";
 import "google/protobuf/timestamp.proto";
 import "google/protobuf/wrappers.proto";
@@ -66,7 +67,7 @@ message ConnectionProperties {
 }
 
 // Defines fields that are shared by all Envoy access logs.
-// [#next-free-field: 21]
+// [#next-free-field: 22]
 message AccessLogCommon {
   // [#not-implemented-hide:]
   // This field indicates the rate at which this log entry was sampled.
@@ -162,6 +163,11 @@ message AccessLogCommon {
   // received. Note: This is always the physical peer, even if the remote address is inferred from
   // for example the x-forwarder-for header, proxy protocol, etc.
   api.v3alpha.core.Address downstream_direct_remote_address = 20;
+
+  // Map of filter state in stream info that have been configured to be logged. If the filter
+  // state serialized to any message other than `google.protobuf.Any` it will be packed into
+  // `google.protobuf.Any`.
+  map<string, google.protobuf.Any> filter_state_objects = 21;
 }
 
 // Flags indicating occurrences during request/response processing.

diff --git a/docs/root/configuration/observability/access_log.rst b/docs/root/configuration/observability/access_log.rst
@@ -353,6 +353,16 @@ The following command operators are supported:
   TCP
     Not implemented ("-").
 
+%FILTER_STATE(KEY):Z%
+  HTTP
+    :ref:`Filter State <arch_overview_data_sharing_between_filters>` info, where the KEY is required to
+    look up the filter state object. The serialized proto will be logged as JSON string if possible.
+    If the serialized proto is unknown to Envoy it will be logged as protobuf debug string.
+    Z is an optional parameter denoting string truncation up to Z characters long.
+
+  TCP
+    Same as HTTP, the filter state is from connection instead of a L7 request.
+
 %REQUESTED_SERVER_NAME%
   HTTP
     String value set on ssl connection socket for Server Name Indication (SNI)

diff --git a/docs/root/intro/arch_overview/advanced/data_sharing_between_filters.rst b/docs/root/intro/arch_overview/advanced/data_sharing_between_filters.rst
@@ -51,7 +51,8 @@ into an instance of `ServicePolicy` class (inherited from
 `FilterState::Object`). When a `Cluster` is created, the associated
 `ServicePolicy` instance will be created and cached. Note that typed
 metadata is not a new source of metadata. It is obtained from metadata that
-is specified as part of the configuration.
+is specified as part of the configuration. A `FilterState::Object` implements
+`serializeAsProto` method can be configured in access loggers to log it.
 
 HTTP Per-Route Filter Configuration
 -----------------------------------

diff --git a/include/envoy/stream_info/BUILD b/include/envoy/stream_info/BUILD
@@ -28,4 +28,5 @@ envoy_cc_library(
     name = "filter_state_interface",
     hdrs = ["filter_state.h"],
     external_deps = ["abseil_optional"],
+    deps = ["//source/common/protobuf"],
 )
diff --git a/include/envoy/stream_info/filter_state.h b/include/envoy/stream_info/filter_state.h
@@ -7,6 +7,7 @@
 #include "envoy/common/pure.h"
 
 #include "common/common/fmt.h"
+#include "common/protobuf/protobuf.h"
 
 #include "absl/strings/string_view.h"
 
@@ -25,6 +26,13 @@ class FilterState {
   class Object {
   public:
     virtual ~Object() = default;
+
+    /**
+     * @return Protobuf::MessagePtr an unique pointer to the proto serialization of the filter
+     * state. If returned message type is ProtobufWkt::Any it will be directly used in protobuf
+     * logging. nullptr if the filter state cannot be serialized or serialization is not supported.
+     */
+    virtual ProtobufTypes::MessagePtr serializeAsProto() const { return nullptr; }
   };
 
   virtual ~FilterState() = default;

diff --git a/source/common/access_log/access_log_formatter.cc b/source/common/access_log/access_log_formatter.cc
@@ -209,22 +209,27 @@ void AccessLogFormatParser::parseCommand(const std::string& token, const size_t
   }
 
   const std::string name_data = token.substr(start, end_request - start);
-  const std::vector<std::string> keys = absl::StrSplit(name_data, separator);
-  if (!keys.empty()) {
-    // The main value is the first key
-    main = keys.at(0);
-    if (keys.size() > 1) {
-      // Sub items contain additional keys
-      sub_items.insert(sub_items.end(), keys.begin() + 1, keys.end());
+  if (!separator.empty()) {
+    const std::vector<std::string> keys = absl::StrSplit(name_data, separator);
+    if (!keys.empty()) {
+      // The main value is the first key
+      main = keys.at(0);
+      if (keys.size() > 1) {
+        // Sub items contain additional keys
+        sub_items.insert(sub_items.end(), keys.begin() + 1, keys.end());
+      }
     }
+  } else {
+    main = name_data;
   }
 }
 
 // TODO(derekargueta): #2967 - Rewrite AccessLogFormatter with parser library & formal grammar
 std::vector<FormatterProviderPtr> AccessLogFormatParser::parse(const std::string& format) {
   std::string current_token;
   std::vector<FormatterProviderPtr> formatters;
-  const std::string DYNAMIC_META_TOKEN = "DYNAMIC_METADATA(";
+  static constexpr absl::string_view DYNAMIC_META_TOKEN{"DYNAMIC_METADATA("};
+  static constexpr absl::string_view FILTER_STATE_TOKEN{"FILTER_STATE("};
   const std::regex command_w_args_regex(R"EOF(%([A-Z]|_)+(\([^\)]*\))?(:[0-9]+)?(%))EOF");
 
   for (size_t pos = 0; pos < format.length(); ++pos) {
@@ -280,6 +285,18 @@ std::vector<FormatterProviderPtr> AccessLogFormatParser::parse(const std::string
         parseCommand(token, start, ":", filter_namespace, path, max_length);
         formatters.emplace_back(
             FormatterProviderPtr{new DynamicMetadataFormatter(filter_namespace, path, max_length)});
+      } else if (absl::StartsWith(token, FILTER_STATE_TOKEN)) {
+        std::string key;
+        absl::optional<size_t> max_length;
+        std::vector<std::string> path;
+        const size_t start = FILTER_STATE_TOKEN.size();
+
+        parseCommand(token, start, "", key, path, max_length);
+        if (key.empty()) {
+          throw EnvoyException("Invalid filter state configuration, key cannot be empty.");
+        }
+
+        formatters.push_back(std::make_unique<FilterStateFormatter>(key, max_length));
       } else if (absl::StartsWith(token, "START_TIME")) {
         const size_t parameters_length = pos + StartTimeParamStart + 1;
         const size_t parameters_end = command_end_position - parameters_length;
@@ -619,6 +636,37 @@ std::string DynamicMetadataFormatter::format(const Http::HeaderMap&, const Http:
   return MetadataFormatter::format(stream_info.dynamicMetadata());
 }
 
+FilterStateFormatter::FilterStateFormatter(const std::string& key,
+                                           absl::optional<size_t> max_length)
+    : key_(key), max_length_(max_length) {}
+
+std::string FilterStateFormatter::format(const Http::HeaderMap&, const Http::HeaderMap&,
+                                         const Http::HeaderMap&,
+                                         const StreamInfo::StreamInfo& stream_info) const {
+  const StreamInfo::FilterState& filter_state = stream_info.filterState();
+  if (!filter_state.hasDataWithName(key_)) {
+    return UnspecifiedValueString;
+  }
+
+  const auto& object = filter_state.getDataReadOnly<StreamInfo::FilterState::Object>(key_);
+  ProtobufTypes::MessagePtr proto = object.serializeAsProto();
+  if (proto == nullptr) {
+    return UnspecifiedValueString;
+  }
+
+  std::string value;
+  const auto status = Protobuf::util::MessageToJsonString(*proto, &value);
+  if (!status.ok()) {
+    // If the message contains an unknown Any (from WASM or Lua), MessageToJsonString will fail.
+    // TODO(lizan): add support of unknown Any.
+    return UnspecifiedValueString;
+  }
+  if (max_length_.has_value() && value.length() > max_length_.value()) {
+    return value.substr(0, max_length_.value());
+  }
+  return value;
+}
+
 StartTimeFormatter::StartTimeFormatter(const std::string& format) : date_formatter_(format) {}
 
 std::string StartTimeFormatter::format(const Http::HeaderMap&, const Http::HeaderMap&,

diff --git a/source/common/access_log/access_log_formatter.h b/source/common/access_log/access_log_formatter.h
@@ -233,6 +233,22 @@ class DynamicMetadataFormatter : public FormatterProvider, MetadataFormatter {
                      const StreamInfo::StreamInfo& stream_info) const override;
 };
 
+/**
+ * Formatter based on the FilterState from StreamInfo.
+ */
+class FilterStateFormatter : public FormatterProvider {
+public:
+  FilterStateFormatter(const std::string& key, absl::optional<size_t> max_length);
+
+  // FormatterProvider::format
+  std::string format(const Http::HeaderMap&, const Http::HeaderMap&, const Http::HeaderMap&,
+                     const StreamInfo::StreamInfo& stream_info) const override;
+
+private:
+  std::string key_;
+  absl::optional<size_t> max_length_;
+};
+
 /**
  * Formatter
  */

diff --git a/source/common/router/string_accessor_impl.h b/source/common/router/string_accessor_impl.h
@@ -12,6 +12,13 @@ class StringAccessorImpl : public StringAccessor {
   // StringAccessor
   absl::string_view asString() const override { return value_; }
 
+  // FilterState::Object
+  ProtobufTypes::MessagePtr serializeAsProto() const override {
+    auto message = std::make_unique<ProtobufWkt::StringValue>();
+    message->set_value(value_);
+    return message;
+  }
+
 private:
   std::string value_;
 };

diff --git a/source/extensions/access_loggers/grpc/BUILD b/source/extensions/access_loggers/grpc/BUILD
@@ -51,6 +51,7 @@ envoy_cc_library(
         "//source/common/network:utility_lib",
         "//source/common/stream_info:stream_info_lib",
         "//source/common/stream_info:utility_lib",
+        "@envoy_api//envoy/config/accesslog/v2:pkg_cc_proto",
         "@envoy_api//envoy/data/accesslog/v2:pkg_cc_proto",
     ],
 )

diff --git a/source/extensions/access_loggers/grpc/grpc_access_log_utils.cc b/source/extensions/access_loggers/grpc/grpc_access_log_utils.cc
@@ -119,7 +119,8 @@ void Utility::responseFlagsToAccessLogResponseFlags(
 
 void Utility::extractCommonAccessLogProperties(
     envoy::data::accesslog::v2::AccessLogCommon& common_access_log,
-    const StreamInfo::StreamInfo& stream_info) {
+    const StreamInfo::StreamInfo& stream_info,
+    const envoy::config::accesslog::v2::CommonGrpcAccessLogConfig& config) {
   // TODO(mattklein123): Populate sample_rate field.
   if (stream_info.downstreamRemoteAddress() != nullptr) {
     Network::Utility::addressToProtobufAddress(
@@ -235,6 +236,23 @@ void Utility::extractCommonAccessLogProperties(
   if (stream_info.dynamicMetadata().filter_metadata_size() > 0) {
     common_access_log.mutable_metadata()->MergeFrom(stream_info.dynamicMetadata());
   }
+
+  for (const auto& key : config.filter_state_objects_to_log()) {
+    if (stream_info.filterState().hasDataWithName(key)) {
+      const auto& obj =
+          stream_info.filterState().getDataReadOnly<StreamInfo::FilterState::Object>(key);
+      ProtobufTypes::MessagePtr serialized_proto = obj.serializeAsProto();
+      if (serialized_proto != nullptr) {
+        auto& filter_state_objects = *common_access_log.mutable_filter_state_objects();
+        ProtobufWkt::Any& any = filter_state_objects[key];
+        if (dynamic_cast<ProtobufWkt::Any*>(serialized_proto.get()) != nullptr) {
+          any.Swap(dynamic_cast<ProtobufWkt::Any*>(serialized_proto.get()));
+        } else {
+          any.PackFrom(*serialized_proto);
+        }
+      }
+    }
+  }
 }
 
 } // namespace GrpcCommon

diff --git a/source/extensions/access_loggers/grpc/grpc_access_log_utils.h b/source/extensions/access_loggers/grpc/grpc_access_log_utils.h
@@ -1,5 +1,6 @@
 #pragma once
 
+#include "envoy/config/accesslog/v2/als.pb.h"
 #include "envoy/data/accesslog/v2/accesslog.pb.h"
 #include "envoy/stream_info/stream_info.h"
 
@@ -10,9 +11,10 @@ namespace GrpcCommon {
 
 class Utility {
 public:
-  static void
-  extractCommonAccessLogProperties(envoy::data::accesslog::v2::AccessLogCommon& common_access_log,
-                                   const StreamInfo::StreamInfo& stream_info);
+  static void extractCommonAccessLogProperties(
+      envoy::data::accesslog::v2::AccessLogCommon& common_access_log,
+      const StreamInfo::StreamInfo& stream_info,
+      const envoy::config::accesslog::v2::CommonGrpcAccessLogConfig& filter_states_to_log);
 
   static void responseFlagsToAccessLogResponseFlags(
       envoy::data::accesslog::v2::AccessLogCommon& common_access_log,

diff --git a/source/extensions/access_loggers/grpc/http_grpc_access_log_impl.cc b/source/extensions/access_loggers/grpc/http_grpc_access_log_impl.cc
@@ -47,7 +47,7 @@ void HttpGrpcAccessLog::emitLog(const Http::HeaderMap& request_headers,
   // TODO(mattklein123): Populate sample_rate field.
   envoy::data::accesslog::v2::HTTPAccessLogEntry log_entry;
   GrpcCommon::Utility::extractCommonAccessLogProperties(*log_entry.mutable_common_properties(),
-                                                        stream_info);
+                                                        stream_info, config_.common_config());
 
   if (stream_info.protocol()) {
     switch (stream_info.protocol().value()) {

diff --git a/source/extensions/access_loggers/grpc/http_grpc_access_log_impl.h b/source/extensions/access_loggers/grpc/http_grpc_access_log_impl.h
@@ -55,6 +55,7 @@ class HttpGrpcAccessLog : public Common::ImplBase {
   std::vector<Http::LowerCaseString> request_headers_to_log_;
   std::vector<Http::LowerCaseString> response_headers_to_log_;
   std::vector<Http::LowerCaseString> response_trailers_to_log_;
+  std::vector<std::string> filter_states_to_log_;
 };
 
 } // namespace HttpGrpc

diff --git a/source/extensions/access_loggers/grpc/tcp_grpc_access_log_impl.cc b/source/extensions/access_loggers/grpc/tcp_grpc_access_log_impl.cc
@@ -31,7 +31,7 @@ void TcpGrpcAccessLog::emitLog(const Http::HeaderMap&, const Http::HeaderMap&,
   // Common log properties.
   envoy::data::accesslog::v2::TCPAccessLogEntry log_entry;
   GrpcCommon::Utility::extractCommonAccessLogProperties(*log_entry.mutable_common_properties(),
-                                                        stream_info);
+                                                        stream_info, config_.common_config());
 
   envoy::data::accesslog::v2::ConnectionProperties& connection_properties =
       *log_entry.mutable_connection_properties();

diff --git a/source/extensions/common/wasm/BUILD b/source/extensions/common/wasm/BUILD
@@ -62,6 +62,9 @@ envoy_cc_library(
 
 envoy_cc_library(
     name = "wasm_interoperation_lib",
+    srcs = [
+        "wasm_state.cc",
+    ],
     hdrs = [
         "wasm_state.h",
     ],