access_log, router: add subsecond specifier for START_TIME by dio · Pull Request #3269 · envoyproxy/envoy

dio · 2018-05-02T10:52:14Z

access_log, router: add subsecond specifier for START_TIME

Description:
This change adds %f, %[1-9]f specifier to get subseconds for START_TIME.
As an example, START_TIME(%s%3f) gets a timestamp in milliseconds.

This also adds START_TIME as one of the supported variables in header formatter.

Risk Level: Low, since this is an optional feature.

Testing: unit and manual tests.

Docs Changes:

added subsecond specifier for START_TIME for both access_log and router header formatter.
added START_TIME as one of the supported variables in header formatter.

Release Notes:

added subsecond specifier for START_TIME for both access_log and router header formatter.
added START_TIME as one of the supported variables in header formatter.

Fixes #1966
Fixes #2877

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

htuch · 2018-05-04T14:28:47Z

@junr03 can you take first pass on this? Thanks.

junr03

two comments

junr03 · 2018-05-07T23:28:53Z

source/common/router/router.cc

 Http::FilterHeadersStatus Filter::decodeHeaders(Http::HeaderMap& headers, bool end_stream) {
  downstream_headers_ = &headers;

+  if (!config_.start_timestamp_header_.get().empty()) {


add an explanation comment

Added in 4c80a6d.

junr03 · 2018-05-08T00:18:44Z

test/common/router/router_test.cc

+  expectResponseTimerCreate();
+
+  Http::TestHeaderMapImpl headers;
+  HttpTestUtility::addDefaultHeaders(headers);


test that the x-request-start header is not present before the call to decodeHeaders

Added in 3110ce0.

#3269 (comment) Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

…e call to decodeHeaders #3269 (comment) Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

junr03

thanks @dio. @htuch can you take a look?

htuch · 2018-05-08T17:26:31Z

api/envoy/config/filter/http/router/v2/router.proto

+  //
+  //   start_timestamp_header: x-request-start
+  //
+  string start_timestamp_header = 4;


Can we reuse the existing user defined headers mechanism for this? E.g. you could configure x-request-start with value %START_TIMESTAMP%?

Oh yes, +1. That seems better.

@htuch thanks for the hint! Yes, I think that's the right direction (I should went to that direction in the first place, since apparently RequestInfo has that useful .startTime() 😔).

I added the corresponding changes using that approach. Thanks!

That's cleaner, thanks for suggesting!

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

mattklein123

Approach looks good. Mostly wonder if we can generalize this even more.

mattklein123 · 2018-05-09T17:28:53Z

docs/root/configuration/http_conn_man/headers.rst

    namespace and key(s) are specified as a JSON array of strings. Finally, percent symbols in the
    parameters **do not** need to be escaped by doubling them.
+
+%START_TIMESTAMP%


We already have START_TIME in access logs. I wonder, could we just use START_TIME and allow a custom format specifier that is effectively milliseconds since epoch? Then we could use the same code in both places. If we can't do that what about START_TIME_SINCE_EPOCH or something? Though I like the former better. Thoughts?

@mattklein123 do you think specifically handling since_epoch_ms in start time formatting makes sense?

i.e. the start time formatting is either:

Using std::put_time's fmt string for %START_TIME(%Y/%m/%dT%H:%M:%S%z %s)%, or

Using fmt::format for %START_TIME(since_epoch_ms)%

However, I think for now we probably can go with START_TIME_SINCE_EPOCH for header formatter, since currently the way AccessLogFormatParser build the formatter is a bit isolated to itself. WDYT?

This is somewhat related to #3256. It would be nice to support custom formatters apart from what is currently supported. cc @bplotnick.

I think if we did this we could support time since epoch and some other things and I think this is a better long term direction, though more work. Are you interested in picking up #3256 as well and working on both?

@mattklein123 sure let me take a look at the possibilities.

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

htuch

LGTM

htuch · 2018-05-10T21:48:59Z

test/common/router/header_formatter_test.cc

      {":method", "POST"}, {"static-header", "old-value"}, {"x-client-ip", "0.0.0.0"}};

  NiceMock<Envoy::RequestInfo::MockRequestInfo> request_info;
+  time_t start_time_epoch = 1522280158;


Nit: const here and below

dio · 2018-05-10T22:20:03Z

@htuch WDYT of this: #3269 (comment)?

Seems like I need update this PR to fulfil that requirement.

htuch · 2018-05-10T22:29:40Z

@dio sure, if you want to followup on that it'd be nice.

mattklein123 · 2018-05-11T04:33:01Z

@dio if adding more custom formatters looks too hard we can punt, but I think it's worth investigating just to see how difficult it would be since I think it would be a cleaner solution.

dio · 2018-05-11T05:30:07Z

@mattklein123 sure. Will give it a try.

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

dio · 2018-05-14T17:34:02Z

@mattklein123 I played around with this a little bit, so far I can have:

"%START_TIME(%since_epoch_ms)%" to get timestamp since epoch in ms (we could have us and ns too).
"%START_TIME(%ms)%" to get the ms component of a start time (we could also extend it to get us and ns component). And yes, it can be combined with the currently strftime supported params.

Do you think this is the right direction?

mattklein123 · 2018-05-14T18:14:51Z

@dio I think if it looks possible to introduce custom formatters, it's the way to go. It's a much cleaner solution and we can solve multiple issues at once.

htuch · 2018-05-15T10:25:58Z

@dio SGTM. Instread of %ms%, how about following other existing conventions for sub-second granularity, e.g. https://bugs.python.org/issue1982?

mattklein123 · 2018-05-15T16:44:51Z

@dio as long as @htuch is good with it, let's move forward with the time formatting extensions. Agree we should use existing conventions in other languages if possible. Let us know when this is updated and ready for review. Thank you!!

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

dio · 2018-06-01T00:19:05Z

@htuch this is updated. When you have time, PTAL. Thanks!

htuch · 2018-06-01T21:39:24Z

source/common/common/utility.cc

-    ASSERT(placeholder_index != std::string::npos);
-    formatted.replace(placeholder_index, width, subsecond);
+  for (const auto subsecond : subseconds_) {
+    // TODO(dio): Infer the length of second from parsing step. Currently, it is defaulted to 10.


Probably needs to be fixed before merging.

htuch · 2018-06-01T21:46:58Z

source/common/common/utility.cc

                              SubsecondConstants::get().PLACEHOLDER.substr(0, width));
+
+    const std::string part = new_format_string.substr(previous, matched.position() - previous);
+    const size_t formatted_length = strftime(&buf[0], buf.size(), part.c_str(), &current_tm);


I think the part above now looks good, but I don't think you want to do anything that uses the current time representation here (it seems dangerous, since the formatted time at parse may be very different than the formatted time at request time). Here's my understanding:

When we parse, we are looking at the string without any substitutions, e.g. %s-%3f-asdf-%9f.

When we substitute, we replace the %Nf before doing the strftime. So, we don't need to do anything here that is post-strftime.

The reason you need to do this additional complexity right now is due to how the cached time string works. I think what makes sense is to do the offset computation when you regenerate the cached item, in conjunctino with the strftime.

Sorry I missed this the first couple of rounds, that's the crux of it I think.

@htuch I decided to have fromTimeAndPrepareSubsecondOffsets to figure out the subsecond offsets of a format string after it is formatted by strftime. Hence I can use it here.

I'm not super happy about it since it is a bit complex. Want to get your input on this. Thanks!

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

dio · 2018-06-03T06:12:45Z

@htuch yet another update. Please take a look when you have time. Thanks!

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

htuch

Thanks for taking the time to try and clean this up. I agree that it's not too pretty either way :/

htuch · 2018-06-04T02:21:41Z

source/common/common/utility.cc

+      std::string str;
+    };
+    // A map is used to keep different formatted format strings at a given second.
+    std::unordered_map<std::string, const Formatted> formatted;


Do we slowly leak via this map? E.g. if I replace route configuration multiple times and change the format strings, do we accumulate and never clear entries?

It seems that is true. We need to find a way to detect when to clear this.

I tried to clear it at each second as exhibited in 513d4bf.

htuch · 2018-06-04T14:45:56Z

source/common/common/utility.cc

+
+  if (cached_time.formatted.find(format_string_) == cached_time.formatted.end() ||
+      cached_time.epoch_time_seconds != epoch_time_seconds) {
+    time_t current_time = std::chrono::system_clock::to_time_t(time);


Nit: const

htuch · 2018-06-04T14:51:33Z

source/common/common/utility.cc

+  const std::string nanoseconds = fmt::FormatInt(epoch_time_ns.count()).str();
+  for (size_t i = 0; i < subseconds_.size(); ++i) {
+    const auto& subsecond = subseconds_.at(i);
+    const std::string digits = nanoseconds.substr(cached_time.seconds_length, subsecond.width_);


This should be absl::string_view I think to avoid copies.

It seems I couldn't do this since it hits stack-use-after-scope.

htuch · 2018-06-04T15:09:58Z

source/common/common/utility.cc

+    const std::string last_segment = format_string_.substr(step);
+    strftime(&buf[0], buf.size(), last_segment.c_str(), &current_tm);
+    absl::StrAppend(&formatted, &buf[0]);
+  }


Wow, yeah, this is complicated, but I'm not sure if there's a simpler way. I'm OK with the above if you clean it up and add comments. Alternatively, we could fragment into segments during the initial parse (which I think is what you may have had in an earlier iteration) and just do the append + substitute here.

I do the pre-computation 96f915e.

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

dio · 2018-06-05T03:49:28Z

@htuch I have another set of updates. Now I tried to pre-compute the segments and add clearance for the cached map of formatted. PTAL. 😄

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

htuch

@dio thanks for your patience and diligence here, I think what you have now looks great. A bunch of feedback, and I think you should have a number of tests for the parse/format code that explore crazy boundary conditions that might arise.

htuch · 2018-06-05T20:22:38Z

source/common/common/utility.cc

 std::string DateFormatter::fromTime(const SystemTime& time) const {
-  return fromTime(std::chrono::system_clock::to_time_t(time));
+  struct CachedTime {
+    size_t seconds_length;


Comment would be useful here.

htuch · 2018-06-05T20:22:50Z

source/common/common/utility.cc

+    struct Formatted {
+      std::string str;
+      SubsecondOffsets subsecond_offsets;
+      std::chrono::seconds epoch_time_seconds;


Can you comment these fields and struct?

htuch · 2018-06-05T22:17:13Z

source/common/common/utility.cc

+  const std::chrono::seconds epoch_time_seconds =
+      std::chrono::duration_cast<std::chrono::seconds>(epoch_time_ns);
+
+  // Remove all the expired cached items.


You could push this loop underneath the if (item == cached_time.formatted.end()) scope, to avoid doing this on the hot path. We only need to GC every now and then, once per second will be fine.

htuch · 2018-06-05T22:51:12Z

source/common/common/utility.cc

+  // To capture the segment after the last subsecond pattern of a format string. E.g.
+  // %3f-this-is-the-last-%s-segment-%Y-until-this.
+  if (step < new_format_string.size()) {
+    last_segment_ = new_format_string.substr(step);


Can you create a dummy zero length subsecond entry to allow this to be treated more uniformly later?

htuch · 2018-06-05T22:51:45Z

source/common/common/utility.cc

+  std::array<char, 1024> buf;
+  std::string formatted;
+
+  int32_t previous = 0;


Nit: prefer using signed types where possible, since they describe the allowed range.

htuch · 2018-06-05T22:58:05Z

source/common/common/utility.cc

+
+class SubsecondConstantValues {
+public:
+  const std::string PLACEHOLDER{"?????????"};


You probably don't need this to be a constant. You can just do something like std::string(N, '?') later on to generate a string of length N.

htuch · 2018-06-05T22:58:22Z

source/common/common/utility.h

+        : position_(position), width_(width), segment_(segment) {}
+
+    const size_t position_;
+    const size_t width_;


Comments on all these fields please.

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

dio · 2018-06-06T10:28:09Z

I think you should have a number of tests for the parse/format code that explore crazy boundary conditions that might arise.

We have:

"%START_TIME(segment1:%s.%3f|segment2:%s.%4f|seg3:%s.%6f|%s-%3f-asdf-%9f|.%7f:segm5:%Y)%" that tests segment with different lengths in between subsecond specifiers
"%START_TIME(%|%%%%|%%%%%f|%s%%%%%3f|%1f%%%%%s)%" that tests if a set of shorter segments with negative offsets matters.

If you have another idea please let me know. 🙂

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

htuch

Two very minor comments and LGTM.

htuch · 2018-06-06T15:25:55Z

source/common/common/utility.cc

+
+    // This computes and saves offset of each subsecond pattern to correct its position after the
+    // previous string segment is formatted.
+    const int32_t offset = formatted_length - subsecond.segment_.size();


Can this be negative?

Yes, e.g. %%%% is formatted as %%.

htuch · 2018-06-06T15:26:34Z

source/common/router/header_formatter.h

 private:
  std::function<std::string(const Envoy::RequestInfo::RequestInfo&)> field_extractor_;
  const bool append_;
+  std::map<std::string, std::vector<AccessLog::FormatterPtr>> start_time_formatters_;


unordered_map?

Ah, OK. Why did I put it as a map? 😅.

@htuch updated.

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

htuch

Rad, thanks!

mattklein123 · 2018-06-07T15:51:56Z

Super cool @dio. Awesome work!

dio added 2 commits May 2, 2018 17:43

router: add start timestamp header config

f85d68d

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

docs: update release notes

b0b741b

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

ggreenway assigned junr03 May 2, 2018

htuch self-assigned this May 3, 2018

junr03 reviewed May 8, 2018

View reviewed changes

dio added 2 commits May 8, 2018 11:54

review: add comment

4c80a6d

#3269 (comment) Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

review: test that the x-request-start header is not present before th…

3110ce0

…e call to decodeHeaders #3269 (comment) Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

junr03 reviewed May 8, 2018

View reviewed changes

htuch reviewed May 8, 2018

View reviewed changes

dio added 4 commits May 9, 2018 09:10

review: use header manipulation facility instead

42bd291

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Merge remote-tracking branch 'upstream/master'

8fcc471

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Add a test sample to TestParseInternal

4e74570

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

tsan: check RatelimitIntegrationTest failure

79a3320

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

mattklein123 reviewed May 9, 2018

View reviewed changes

dio added 2 commits May 10, 2018 06:58

Rename it to START_TIME_SINCE_EPOCH

f94e020

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Fix format

07dc56f

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

htuch reviewed May 10, 2018

View reviewed changes

dio added 3 commits May 14, 2018 07:21

Merge remote-tracking branch 'upstream/master'

91fb3da

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Allow header parser to accept START_TIME(ARG)

aef2ed9

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Add replacers

1970913

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Use %f as subsecond formatter

9004414

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

dio added 2 commits June 1, 2018 06:32

No more find()

8a1571f

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Merge remote-tracking branch 'upstream/master'

78e8430

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

htuch suggested changes Jun 1, 2018

View reviewed changes

dio added 4 commits June 3, 2018 05:26

Move subsecond offsets computation

325fdc5

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Merge remote-tracking branch 'upstream/master'

4b9fa9e

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Move the offsets calc to fromTimeAndPrepareSubsecondOffsets

9aba1e9

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Cleanup unused deps and vars

94e3add

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Infer seconds_length only when it is needed

612f829

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

htuch reviewed Jun 4, 2018

View reviewed changes

dio added 2 commits June 5, 2018 09:30

Precompute the string segments between specifiers

96f915e

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Try to fix asan on using stack after scope: digits

d5f082b

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

dio added 2 commits June 5, 2018 15:39

Stamp per cache item.

b85b275

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Fix removing an item of a map while iterating it

513d4bf

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

mattklein123 mentioned this pull request Jun 5, 2018

Access log's timestamps are still in UTC regardless a containter's timezone? #3546

Closed

htuch suggested changes Jun 5, 2018

View reviewed changes

dio added 4 commits June 6, 2018 17:21

Remove const PLACEHOLDER

9a16090

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Add comments to CachedTime struct

e5642ba

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Remove last_segment_ and streamline replacement

bda6762

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Add test with shorter segments

ec35f6c

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Remove % since it is diff on osx vs. linux

ea5e62f

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

htuch reviewed Jun 6, 2018

View reviewed changes

dio added 2 commits June 6, 2018 23:37

Use unordered_map instead

22a94a4

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

Comment on the possibility to have negative offset value

3f01c64

Signed-off-by: Dhi Aurrahman <dio@rockybars.com>

htuch approved these changes Jun 6, 2018

View reviewed changes

htuch merged commit bc1b39c into envoyproxy:master Jun 6, 2018

Conversation

dio commented May 2, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

htuch commented May 4, 2018

Uh oh!

junr03 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!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

junr03 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!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mattklein123 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!

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!

htuch left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dio commented May 10, 2018

Uh oh!

htuch commented May 10, 2018

Uh oh!

mattklein123 commented May 11, 2018

Uh oh!

dio commented May 11, 2018

Uh oh!

dio commented May 14, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mattklein123 commented May 14, 2018

Uh oh!

htuch commented May 15, 2018

Uh oh!

mattklein123 commented May 15, 2018

Uh oh!

dio commented Jun 1, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dio Jun 3, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dio commented Jun 3, 2018

Uh oh!

htuch left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

dio commented May 2, 2018 •

edited

Loading

dio commented May 14, 2018 •

edited

Loading

dio Jun 3, 2018 •

edited

Loading

dio Jun 5, 2018 •

edited

Loading