access_log: support for dynamic metadata set as part of the request info by glicht · Pull Request #2895 · envoyproxy/envoy

glicht · 2018-03-24T13:04:40Z

Description: Relates to issue #1278. Added new dynamic Metadata object to request_info (accessed via request_info.dynamicMetadata()). Dynamic Metadata can be set by filters and consumed by either other filters or the access log. Added to the access_log an option to specify logging of dynamic metadata through the following access log format token: %DYNAMIC_METADATA(filter_namespace:key*):Z%. "Z" is an optional parameter denoting max length. It is possible to have a nested key path. Each key is separated by ':'. For example for the following dynamic metadata:

com.test.my_filter: {"test_key": "foo", "test_object": {"inner_key": "bar"}}

%DYNAMIC_METADATA(com.test.my_filter)% will log: {"test_key": "foo", "test_object": {"inner_key": "bar"}}
%DYNAMIC_METADATA(com.test.my_filter:test_key)% will log: "foo"
%DYNAMIC_METADATA(com.test.my_filter:test_object)% will log: {"inner_key": "bar"}
%DYNAMIC_METADATA(com.test.my_filter:test_object:inner_key)% will log: "bar"

Risk Level: Low
Testing: unit tests added to access_log_formatter_test and request_info_impl_test. I've done manual testing with a custom "body parser" filter which parses the request body and stores the parsed result in the dynamic metadata of request_info. If this is of interest, I am ok with contributing this filter too.

Docs Changes: envoyproxy/data-plane-api#590

Signed-off-by: Guy Lichtman <[email protected]>

mattklein123 · 2018-03-26T16:54:42Z

@rodaine can you please review this also? Thank you.

rodaine

LGTM, just one minor comment on supporting unsetting values

rodaine · 2018-03-28T00:46:42Z

include/envoy/request_info/request_info.h

+   * values for the same key overriding existing.
+   */
+  virtual void setDynamicMetadata(const std::string& name, const std::string& key,
+                                  const std::string& value) PURE;


Do you think we'll need to support an unset?

I didn't really think about a use case which needs the clear option. I kind of envisioned this as append only with possible over write of existing values.

mattklein123 · 2018-03-28T21:08:52Z

@glicht quick note: Do you mind doing the parallel doc/release note PR in data-plane-api so we can review it together?

glicht · 2018-03-29T06:28:01Z

Sure. Will add the documentation soon.

documentation for PR: envoyproxy/envoy#2895 Signed-off-by: Guy Lichtman <[email protected]>

glicht · 2018-03-29T09:03:00Z

Documentation PR is available at: envoyproxy/data-plane-api#590

documentation for PR: envoyproxy/envoy#2895 Signed-off-by: Guy Lichtman <[email protected]>

htuch · 2018-04-02T16:55:35Z

source/common/access_log/access_log_formatter.cc

+  return json;
+}
+
+DynamicMetadataFormatter::DynamicMetadataFormatter(const std::string& filter_namespace,


Since we're going to the effort to add support for ASCII logging of dynamic metadata, how about adding in support for logging the other forms of metadata? Or at least a TODO, I think most of this is highly reusable for logging route, listener, cluster etc. metadata.

I am not sure I have a good understanding of the various use cases that one would want to log route/listener/cluster metadata. I can add a TODO note, and if someone needs this info in the log they can add the functionality.

That's fine. There are definitely useful situations for this, e.g. if you have a multitenant environment and want to add per-tenant identifiers to routes or listeners.

htuch · 2018-04-02T16:56:24Z

include/envoy/request_info/request_info.h

+  virtual const envoy::api::v2::core::Metadata& dynamicMetadata() const PURE;
+
+  /**
+   * @param name the namespace used in the metadata in reverse dns format for example:


Nit: s/in reverse dns format for example/in reverse DNS format, for example/

htuch · 2018-04-02T16:58:12Z

include/envoy/request_info/request_info.h

+   * @param value the string value to associate with the key. A merge will be performed with new
+   * values for the same key overriding existing.
+   */
+  virtual void setDynamicMetadata(const std::string& name, const std::string& key,


I don't think this needs to be part of the abstract interface, this can just be a static utility method that operates on the above setDynamicMetadata.

OK. Will remove and add a static keyValueStruct method to common/protobuf/utility.h

htuch · 2018-04-02T17:06:07Z

source/common/access_log/access_log_formatter.cc

+
+        parseCommand(token, start, ":", filter_namespace, path, max_length);
+        formatters.emplace_back(
+            FormatterPtr(new DynamicMetadataFormatter(filter_namespace, path, max_length)));


You can probably skip the explicit FormatterPtr here, since this is emplace_back.

Will take a look. Note that the existing formatters also use this pattern.

htuch · 2018-04-02T17:07:22Z

source/common/access_log/access_log_formatter.cc

  } else {
-    main_header = header_name.substr(0, separator);
-    alternative_header = header_name.substr(separator + 1, end_request - separator - 1);
+    main = name_data.substr(0, separator_pos);


Can you add comments/examples of what is going on here, it's a bit hard to process without context.

htuch · 2018-04-02T17:10:17Z

source/common/access_log/access_log_formatter.h

+                                 absl::optional<size_t>& max_length);
+  static void parseCommand(const std::string& token, const size_t start,
+                           const std::string& separator, std::string& main,
+                           std::vector<std::string>& subs, absl::optional<size_t>& max_length);


I think some comments on what subs are and the expected pre/postconditions would be helpful.

htuch · 2018-04-02T17:12:05Z

source/common/access_log/access_log_formatter.cc

+  if (filter_it == metadata.filter_metadata().end()) {
+    return UnspecifiedValueString;
+  }
+  const ProtobufWkt::Struct* dataStruct = &(filter_it->second);


Nit: s/dataStruct/data_struct/

htuch · 2018-04-02T17:15:17Z

source/common/access_log/access_log_formatter.cc

+  const ProtobufWkt::Struct* dataStruct = &(filter_it->second);
+  const Protobuf::Message* data = dataStruct;
+  // go through path to select sub entries
+  for (const auto p : path_) {


Can you refactor this lookup part of the method to be a general lookup helper in https://github.com/envoyproxy/envoy/blob/master/source/common/config/metadata.h?

htuch · 2018-04-02T17:15:53Z

source/common/access_log/access_log_formatter.h

+public:
+  DynamicMetadataFormatter(const std::string& filter_namespace,
+                           const std::vector<std::string>& path,
+                           const absl::optional<size_t>& max_length);


It's probably not worth passing this one by ref, it will be a tiny object that can fit in a register.

It's the same pattern as used in the other formatters: ResponseHeaderFormatter/RequestHeaderFormatter.

htuch · 2018-04-02T17:16:55Z

source/common/access_log/access_log_formatter.cc

+    return UnspecifiedValueString;
+  }
+  const ProtobufWkt::Struct* dataStruct = &(filter_it->second);
+  const Protobuf::Message* data = dataStruct;


I'd skip this in the loop, it's a superfluous alias.

Added additional comments, small text naming fixes, refactored out utility methods, added more tests Signed-off-by: Guy Lichtman <[email protected]>

Signed-off-by: Guy Lichtman <[email protected]>

htuch · 2018-04-03T20:48:33Z

source/common/config/metadata.cc

+    if (val->has_struct_value()) {
+      dataStruct = &(val->struct_value());
+    } else {
+      dataStruct = nullptr;


Use data_struct rather than dataStruct.

htuch · 2018-04-03T20:50:08Z

test/common/config/metadata_test.cc

+  ProtobufWkt::Value val;
+  *val.mutable_struct_value() = obj;
+  (*filter_struct.mutable_fields())["test_obj"] = val;
+  EXPECT_EQ(Metadata::metadataValue(metadata, filter, path).string_value(), "inner_value");


Are you covering all the failure branches here? https://37371-65214191-gh.circle-artifacts.com/0/build/envoy/generated/coverage/coverage.source_common_config_metadata.cc.html

Latest commit covers all failure branches: https://37602-65214191-gh.circle-artifacts.com/0/build/envoy/generated/coverage/coverage.source_common_config_metadata.cc.html

htuch · 2018-04-03T20:50:52Z

test/common/request_info/request_info_impl_test.cc

+            Config::Metadata::metadataValue(request_info.dynamicMetadata(), "com.test", "test_key")
+                .string_value());
+  std::string json;
+  const auto testStruct = request_info.dynamicMetadata().filter_metadata().at("com.test");


Please switch away from this snake case for local everywhere.

htuch · 2018-04-03T20:52:33Z

source/common/access_log/access_log_formatter.h

+   * "main" and any additional sub values will be set in the vector "subs". For example token of:
+   * "com.test.my_filter:test_object:inner_key):100" with separator of ":" will set the following:
+   * - main: com.test.my_filter
+   * - subs: {test_object, inner_key}


I would rename this something like subitems, I kept expecting this to be a "substitution" list.

htuch · 2018-04-03T20:53:16Z

source/common/access_log/access_log_formatter.h

+                                 std::string& main_header, std::string& alternative_header,
+                                 absl::optional<size_t>& max_length);
+  /**
+   * General parse command utility. Will parse token from start position. Token is expected to end


Please add a TODO and link to #2967, this code is all getting quite hairy.

added in latest commit

htuch · 2018-04-03T20:54:42Z

source/common/access_log/access_log_formatter.cc

+  parseCommand(token, start, "?", main_header, subs, max_length);
+  if (subs.size() > 1) {
+    throw EnvoyException(
+        fmt::format("More than 1 alternative header specified in token: {}", token));


At this point I've lost track of what an alternative header is. Should the exception message or a comment be added to explain?

htuch · 2018-04-03T20:55:19Z

source/common/access_log/access_log_formatter.cc

+        fmt::format("More than 1 alternative header specified in token: {}", token));
+  }
+  if (subs.size() == 1) {
+    alternative_header = subs.front();


This method has no comment, so I don't know what alternative_header assignment means.

…ments and syntax corrections Signed-off-by: Guy Lichtman <[email protected]>

ccaraman · 2018-04-04T19:10:03Z

source/common/access_log/access_log_formatter.cc

-    main_header = header_name;
-    alternative_header = "";
+  if (separator_pos == std::string::npos) {
+    // no separator -> main value is simply the whole data


Please use complete sentences for comments.

And can the comment be expanded that the first entry is meant to be the namespace and the sub_items is the key/path to the values that are desired to be printed?

ccaraman · 2018-04-04T19:38:21Z

source/common/access_log/access_log_formatter.cc

 void AccessLogFormatParser::parseCommand(const std::string& token, const size_t start,
-                                         std::string& main_header, std::string& alternative_header,
+                                         const std::string& separator, std::string& main,
+                                         std::vector<std::string>& subitems,


nit: sub_items

ccaraman · 2018-04-04T19:46:39Z

source/common/access_log/access_log_formatter.cc

+}
+
+// TODO(glicht): Consider adding support for route/listener/cluster metadata as suggested by @htuch.
+// See: https://github.com/envoyproxy/envoy/pull/2895#pullrequestreview-108668292


the link doesn't work anymore. Can an issue be created instead to track this ask?

I've opened issue #3006 and will change the link in the comment

ccaraman · 2018-04-04T19:58:23Z

source/common/access_log/access_log_formatter.cc

-  std::string header_name = token.substr(start, end_request - start);
-  size_t separator = header_name.find('?');
+  std::string name_data = token.substr(start, end_request - start);
+  size_t separator_pos = name_data.find(separator);


You can use 'absl::StrSplit' instead to simplify the next set of lines

good idea. will do.

ccaraman · 2018-04-04T19:58:46Z

source/common/access_log/access_log_formatter.h

+  static void parseCommandHeader(const std::string& token, const size_t start,
+                                 std::string& main_header, std::string& alternative_header,
+                                 absl::optional<size_t>& max_length);
+  /**


nit: add a new line before this line

ccaraman · 2018-04-04T19:59:29Z

source/common/access_log/access_log_formatter.h

+   * @param token the token to parse
+   * @param start the index to start parsing from
+   * @param seperator seperator between values
+   * @param main the first value


nit: namespace might be a better name to match naming pattern across the code base.

For metadata, namespace fits, but for the header commands it doesn't. I would leave it as is.

ccaraman · 2018-04-04T19:59:41Z

source/common/access_log/access_log_formatter.h

+   * @param start the index to start parsing from
+   * @param seperator seperator between values
+   * @param main the first value
+   * @param subitems any additional values


nit: sub_items

… use of StrSplit Signed-off-by: Guy Lichtman <[email protected]>

glicht · 2018-04-05T12:50:14Z

circleci seems to be failing on network issues:

ERROR: /source/bazel/repositories.bzl:203:5: no such package '@boringssl//': Traceback (most recent call last):
File "/build/tmp/_bazel_bazel/436badd4919a15958fa3800a4e21074a/external/bazel_tools/tools/build_defs/repo/git.bzl", line 69
_clone_or_update(ctx)
File "/build/tmp/_bazel_bazel/436badd4919a15958fa3800a4e21074a/external/bazel_tools/tools/build_defs/repo/git.bzl", line 44, in _clone_or_update
fail(("error cloning %s:\n%s" % (ctx....)))
error cloning boringssl:

cd /build/tmp/_bazel_bazel/436badd4919a15958fa3800a4e21074a/external
rm -rf /build/tmp/_bazel_bazel/436badd4919a15958fa3800a4e21074a/external/boringssl
git clone https://boringssl.googlesource.com/boringssl /build/tmp/_bazel_bazel/436badd4919a15958fa3800a4e21074a/external/boringssl
Cloning into '/build/tmp/_bazel_bazel/436badd4919a15958fa3800a4e21074a/external/boringssl'...
fatal: unable to access 'https://boringssl.googlesource.com/boringssl/': Failed to connect to boringssl.googlesource.com port 443: Network is unreachable
and referenced by '//external:ssl'

htuch · 2018-04-05T15:31:23Z

@glicht you need to merge master. We've switched the BorginSSL repo to GitHub to avoid this known CI issue (also, there are a bunch of conflicts to merge with now that the time format PR has merged).

htuch · 2018-04-05T16:19:25Z

source/common/config/metadata.cc

 const ProtobufWkt::Value& Metadata::metadataValue(const envoy::api::v2::core::Metadata& metadata,
                                                  const std::string& filter,
-                                                  const std::string& key) {
+                                                  const std::vector<std::string> path) {


const std::vector<std::string>& path

htuch · 2018-04-05T16:20:07Z

source/common/protobuf/utility.cc

+  ProtobufWkt::Value val;
+  val.set_string_value(value);
+  (*structObj.mutable_fields())[key] = val;
+  return structObj;


Still need to replace some fooBar for locals with foo_bar. Would really appreciate if you could clean this up globally. Thanks!

htuch · 2018-04-05T16:20:36Z

test/common/access_log/access_log_formatter_test.cc

+ * "com.test": {"test_key":"test_value","test_obj":{"inner_key":"inner_value"}}
+ */
+void populateMetadataTestData(envoy::api::v2::core::Metadata& metadata) {
+  ProtobufWkt::Struct structObj;


Ditto.....!

Signed-off-by: Guy Lichtman <[email protected]>

…data.cc, syntax corrections Signed-off-by: Guy Lichtman <[email protected]>

htuch

Thanks!

…nfo (#590) documentation for PR: envoyproxy/envoy#2895 Signed-off-by: Guy Lichtman <[email protected]>

access_log: support for dynamic metadata set as part of the request info

c4581a2

Signed-off-by: Guy Lichtman <[email protected]>

glicht mentioned this pull request Mar 25, 2018

Metadata support in access logs #1278

Closed

alyssawilk assigned htuch and ccaraman Mar 26, 2018

mattklein123 assigned rodaine Mar 26, 2018

rodaine approved these changes Mar 28, 2018

View reviewed changes

glicht added a commit to glicht/data-plane-api that referenced this pull request Mar 29, 2018

access_log: support for dynamic metadata set as part of the request info

2aba9e5

documentation for PR: envoyproxy/envoy#2895 Signed-off-by: Guy Lichtman <[email protected]>

glicht mentioned this pull request Mar 29, 2018

access_log: support for dynamic metadata set as part of the request info envoyproxy/data-plane-api#590

Merged

glicht added a commit to glicht/data-plane-api that referenced this pull request Mar 29, 2018

docs: fix format for access log formatter

3a747e4

documentation for PR: envoyproxy/envoy#2895 Signed-off-by: Guy Lichtman <[email protected]>

glicht added a commit to glicht/data-plane-api that referenced this pull request Mar 31, 2018

access_log: added examples of unknown key logging in DYNAMIC_METADATA

428b00e

documentation for PR: envoyproxy/envoy#2895 Signed-off-by: Guy Lichtman <[email protected]>

htuch suggested changes Apr 2, 2018

View reviewed changes

glicht added 2 commits April 3, 2018 19:36

access_log: support for dynamic metadata - code review fixes

f381b74

Added additional comments, small text naming fixes, refactored out utility methods, added more tests Signed-off-by: Guy Lichtman <[email protected]>

access_log: support for dynamic metadata - format fix

190d4ae

Signed-off-by: Guy Lichtman <[email protected]>

htuch suggested changes Apr 3, 2018

View reviewed changes

htuch mentioned this pull request Apr 3, 2018

access_log: ability to format start_time access log variable #2907

Merged

access_log: dynamic metadata - improved test code coverage, added com…

ec69501

…ments and syntax corrections Signed-off-by: Guy Lichtman <[email protected]>

ccaraman reviewed Apr 4, 2018

View reviewed changes

glicht mentioned this pull request Apr 5, 2018

access_log: support for logging route/listener/cluster metadata #3006

Open

access_log: dynamic metadata - improved comments, syntax corrections,…

4719376

… use of StrSplit Signed-off-by: Guy Lichtman <[email protected]>

htuch reviewed Apr 5, 2018

View reviewed changes

glicht added 2 commits April 8, 2018 01:20

Merge remote-tracking branch 'upstream/master' into dynamic-metadata

e15cd85

Signed-off-by: Guy Lichtman <[email protected]>

access_log: dynamic metadata - code review fixes: pass by ref in meta…

5dbf63e

…data.cc, syntax corrections Signed-off-by: Guy Lichtman <[email protected]>

htuch approved these changes Apr 9, 2018

View reviewed changes

htuch merged commit 2bda629 into envoyproxy:master Apr 9, 2018

htuch pushed a commit to envoyproxy/data-plane-api that referenced this pull request Apr 9, 2018

access_log: support for dynamic metadata set as part of the request i…

a32c7f5

…nfo (#590) documentation for PR: envoyproxy/envoy#2895 Signed-off-by: Guy Lichtman <[email protected]>

Elite1015 pushed a commit to Elite1015/data-plane-api that referenced this pull request Feb 23, 2025

access_log: support for dynamic metadata set as part of the request i…

71927be

…nfo (#590) documentation for PR: envoyproxy/envoy#2895 Signed-off-by: Guy Lichtman <[email protected]>

Conversation

glicht commented Mar 24, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mattklein123 commented Mar 26, 2018

Uh oh!

rodaine left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mattklein123 commented Mar 28, 2018

Uh oh!

glicht commented Mar 29, 2018

Uh oh!

glicht commented Mar 29, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

glicht commented Mar 24, 2018 •

edited

Loading