http: periodic HCM access logs #25824

paul-r-gall · 2023-02-28T19:52:12Z

Commit Message: http: periodic HCM access logs
Additional Description: Make it possible to log periodically from the HCM. This parallels the work already done in TcpProxy.
Risk Level: low
Testing: unit tests.
Docs Changes: none
[Optional Runtime guard:]
[Optional Fixes #Issue]
[Optional Fixes commit #PR or SHA]
[Optional Deprecated:]
[Optional API Considerations:]

Signed-off-by: Paul Gallagher <pgal@google.com>

repokitteh-read-only · 2023-02-28T19:52:32Z

CC @envoyproxy/api-shepherds: Your approval is needed for changes made to (api/envoy/|docs/root/api-docs/).
envoyproxy/api-shepherds assignee is @mattklein123
CC @envoyproxy/api-watchers: FYI only for changes made to (api/envoy/|docs/root/api-docs/).

🐱

Caused by: #25824 was opened by paul-r-gall.

see: more, trace.

kyessenov · 2023-02-28T19:56:16Z

api/envoy/extensions/filters/network/http_connection_manager/v3/http_connection_manager.proto

+  // at the specified interval. This is especially useful in the case of long-lived requests, such as
+  // CONNECT and Websockets.
+  // The interval must be at least 1 second.
+  google.protobuf.Duration access_log_flush_interval = 53


I think it would be useful to log on stream open/close as well.

stream close is already logged via the normal process, right?

Yeah, but it's not clear from the description. Stream open is certainly useful for long running operations.

This was supported in the TCP proxy. It would be better to keep both fields have similar behavior.
https://www.envoyproxy.io/docs/envoy/latest/api-v3/extensions/filters/network/tcp_proxy/v3/tcp_proxy.proto

Added comment clarifying the stream close, as well as adjusted the min duration to 1ms to align w/ TCP Proxy.

repokitteh-read-only · 2023-02-28T20:06:52Z

https://github.com/orgs/envoyproxy/teams/first-pass-reviewers assignee is @None

🐱

Caused by: a #25824 (comment) was created by @paul-r-gall.

see: more, trace.

paul-r-gall · 2023-02-28T20:07:33Z

/assign-from @envoyproxy/first-pass-reviewers

repokitteh-read-only · 2023-02-28T20:07:39Z

@envoyproxy/first-pass-reviewers assignee is @tonya11en

🐱

Caused by: a #25824 (comment) was created by @paul-r-gall.

see: more, trace.

Signed-off-by: Paul Gallagher <pgal@google.com>

mattklein123

This will need a release note. I'm not sure what is done in TCP proxy, but is there any clear way to understand whether the log is an interval log vs. the final log? If so I might also make that clear in the API field description.

/wait

Signed-off-by: Paul Gallagher <pgal@google.com>

api/envoy/extensions/filters/network/http_connection_manager/v3/http_connection_manager.proto

test/common/http/conn_manager_impl_test.cc

kyessenov · 2023-03-03T20:40:06Z

api/envoy/extensions/filters/network/http_connection_manager/v3/http_connection_manager.proto

+  // logs periodically at the specified interval. This is especially useful in the case of long-lived
+  // requests, such as CONNECT and Websockets. Final access logs can be detected via the
+  // `requestComplete()` method of `StreamInfo`.
+  // The interval must be at least 1 millisecond.


I mentioned this privately - but I'm a bit concerned about the unexpected filter interactions. I think some filters register for onLog as some sort of end-of-stream signal. Wasm, for example. Once they start getting multiple calls, they might do something weird. There are two ways I can think of:

make filters deal with it, there are other callbacks onStreamComplete and onDestroy.

make this setting finer grained, e.g. per access log formatter.

If we go with this change (option 1), we should warn downstream projects about a possible bad interaction.

Yeah that's a good point. With that said, this is an opt-in feature so maybe it's ok while we sort out issues like that? I could go either way.

Yeah, I think this is a good feature so we should bring it in. Mostly concerned about how to minimize disruption.

I updated the comment, and the changelog description, in addition to adding a check in the WASM filter.

Signed-off-by: Paul Gallagher <pgal@google.com>

kyessenov

Getting close to completing, just a few more comments.
/wait

kyessenov · 2023-03-08T03:13:02Z

changelogs/current.yaml

+  change: |
+    add :ref:`periodic access logging <envoy_v3_api_field_extensions.filters.network.http_connection_manager.v3.HttpConnectionManager.access_log_flush_interval>`
+    to http access logs for long-lived requests (Websockets, CONNECT, etc). :ref:`%DURATION% <config_access_log_format_duration>` will
+    be empty for mid-request logs. Enabling this may affect access loggers that expect to be called only once.


_ and filters that register as access loggers_

kyessenov · 2023-03-08T03:23:40Z

test/extensions/filters/http/wasm/wasm_filter_test.cc

  StreamInfo::MockStreamInfo log_stream_info;
+  EXPECT_CALL(log_stream_info, requestComplete()).WillRepeatedly(testing::Return(absl::nullopt));
  filter().log(&request_headers, nullptr, nullptr, log_stream_info);


Not sure this actually checks that Wasm log() is not called here? Is this the same check as for regular access log?

Added a clarifying EXPECT_CALL(...).Times(0);

kyessenov · 2023-03-08T03:28:29Z

test/common/http/conn_manager_impl_test.cc

+  filter->callbacks_->encodeHeaders(std::move(response_headers), true, "details");
+}
+
+TEST_F(HttpConnectionManagerImplTest, TestNoPeriodicAccessLoggingWithRequestComplete) {


Not sure what this test does that's different from above, can you elaborate?

Removed this test -- I was trying to get a test going that makes the timer go off in a race-condition way with the stream being completed, but couldn't quite figure out how to do it.

kyessenov · 2023-03-08T03:30:02Z

source/extensions/common/wasm/context.cc

@@ -1457,6 +1457,11 @@ void Context::log(const Http::RequestHeaderMap* request_headers,
                  const Http::ResponseHeaderMap* response_headers,
                  const Http::ResponseTrailerMap* response_trailers,
                  const StreamInfo::StreamInfo& stream_info) {
+  // `log` may be called multiple times due to mid-request logging -- we only want to run on the
+  // last call.
+  if (!stream_info.requestComplete().has_value()) {


I think we'll probably want Wasm access logs to conform, just not Wasm HTTP filters. Both share the code, so I imagine it's tricky to untangle. Maybe leave a comment or issue for later.

Not sure what you mean -- i.e. the access logger should have the ability to write mid-connection logs, but the filter should not?

Yeah, there are two different extension points - Wasm HTTP filters and Wasm access loggers. I guess it makes sense to make them both support periodic reporting at the same time, rather than just Wasm access loggers.

Signed-off-by: Paul Gallagher <pgal@google.com>

kyessenov

LGTM
Would be good to get a non-Googler take a look at the core code as well.

wbpcode

LGTM. Thanks.

wbpcode · 2023-03-10T01:56:47Z

Please resolve the conflict first, then we can merge this patch. Thanks. 😄

Signed-off-by: Paul Gallagher <pgal@google.com>

http: periodic HCM access logs

fd2bb5a

Signed-off-by: Paul Gallagher <pgal@google.com>

paul-r-gall requested review from alyssawilk and mattklein123 as code owners February 28, 2023 19:52

repokitteh-read-only bot added the api label Feb 28, 2023

repokitteh-read-only bot assigned mattklein123 Feb 28, 2023

kyessenov reviewed Feb 28, 2023

View reviewed changes

repokitteh-read-only bot assigned tonya11en Feb 28, 2023

paul-r-gall added 4 commits March 1, 2023 09:13

align with TCP proxy

ea15165

Signed-off-by: Paul Gallagher <pgal@google.com>

fix impls of ConnectionManagerConfig

6104c14

Signed-off-by: Paul Gallagher <pgal@google.com>

fix fuzzer

cd7e5b1

Signed-off-by: Paul Gallagher <pgal@google.com>

fix format

b8fe729

Signed-off-by: Paul Gallagher <pgal@google.com>

mattklein123 assigned kyessenov and unassigned tonya11en Mar 2, 2023

mattklein123 reviewed Mar 2, 2023

View reviewed changes

repokitteh-read-only bot added the waiting label Mar 2, 2023

final log has responseComplete()

b282835

Signed-off-by: Paul Gallagher <pgal@google.com>

repokitteh-read-only bot removed the waiting label Mar 2, 2023

paul-r-gall added 3 commits March 2, 2023 17:10

Merge remote-tracking branch 'upstream/main' into PeriodicHttpLogging

d6084f0

Signed-off-by: Paul Gallagher <pgal@google.com>

release note

bdad3cd

Signed-off-by: Paul Gallagher <pgal@google.com>

fix proto numbering

143e8d3

Signed-off-by: Paul Gallagher <pgal@google.com>

kyessenov reviewed Mar 3, 2023

View reviewed changes

api/envoy/extensions/filters/network/http_connection_manager/v3/http_connection_manager.proto Outdated Show resolved Hide resolved

kyessenov reviewed Mar 3, 2023

View reviewed changes

test/common/http/conn_manager_impl_test.cc Outdated Show resolved Hide resolved

kyessenov reviewed Mar 3, 2023

View reviewed changes

test/common/http/conn_manager_impl_test.cc Outdated Show resolved Hide resolved

kyessenov reviewed Mar 3, 2023

View reviewed changes

paul-r-gall added 2 commits March 6, 2023 08:53

address comments

6eec024

Signed-off-by: Paul Gallagher <pgal@google.com>

merge upstream

84db0e2

Signed-off-by: Paul Gallagher <pgal@google.com>

paul-r-gall requested a review from lizan as a code owner March 6, 2023 13:55

mattklein123 removed their assignment Mar 6, 2023

paul-r-gall added 2 commits March 7, 2023 07:53

fix docs

ed7433c

Signed-off-by: Paul Gallagher <pgal@google.com>

fix wasm tests

3ce99f4

Signed-off-by: Paul Gallagher <pgal@google.com>

kyessenov mentioned this pull request Mar 8, 2023

use standard Envoy interval reporting for telemetry istio/istio#43763

Closed

kyessenov reviewed Mar 8, 2023

View reviewed changes

repokitteh-read-only bot added the waiting label Mar 8, 2023

address comments

f1c7c6b

Signed-off-by: Paul Gallagher <pgal@google.com>

repokitteh-read-only bot removed the waiting label Mar 8, 2023

kyessenov previously approved these changes Mar 9, 2023

View reviewed changes

kyessenov assigned wbpcode Mar 9, 2023

wbpcode previously approved these changes Mar 10, 2023

View reviewed changes

merge upstream

9da04aa

Signed-off-by: Paul Gallagher <pgal@google.com>

paul-r-gall dismissed stale reviews from wbpcode and kyessenov via 9da04aa March 10, 2023 16:51

kyessenov approved these changes Mar 10, 2023

View reviewed changes

kyessenov enabled auto-merge (squash) March 10, 2023 17:56

kyessenov merged commit e11d5de into envoyproxy:main Mar 10, 2023

mattklein123 mentioned this pull request Mar 15, 2023

api: audit_log api specific to RBAC http filters #26001

Merged

kyessenov mentioned this pull request Mar 21, 2023

access_logs: resolve current duration for %DURATION% #26203

Merged

ohadvano mentioned this pull request Apr 13, 2023

router: add periodic upstream access log option #26733

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

http: periodic HCM access logs #25824

http: periodic HCM access logs #25824

paul-r-gall commented Feb 28, 2023

repokitteh-read-only bot commented Feb 28, 2023

kyessenov Feb 28, 2023

paul-r-gall Feb 28, 2023

kyessenov Feb 28, 2023

wbpcode Mar 1, 2023

paul-r-gall Mar 1, 2023

repokitteh-read-only bot commented Feb 28, 2023

paul-r-gall commented Feb 28, 2023

repokitteh-read-only bot commented Feb 28, 2023

mattklein123 left a comment

kyessenov Mar 3, 2023

mattklein123 Mar 6, 2023

kyessenov Mar 6, 2023

paul-r-gall Mar 7, 2023

kyessenov left a comment

kyessenov Mar 8, 2023

kyessenov Mar 8, 2023

paul-r-gall Mar 8, 2023

kyessenov Mar 8, 2023

paul-r-gall Mar 8, 2023

kyessenov Mar 8, 2023

paul-r-gall Mar 8, 2023

kyessenov Mar 8, 2023

kyessenov left a comment

wbpcode left a comment

wbpcode commented Mar 10, 2023

http: periodic HCM access logs #25824

http: periodic HCM access logs #25824

Conversation

paul-r-gall commented Feb 28, 2023

repokitteh-read-only bot commented Feb 28, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

repokitteh-read-only bot commented Feb 28, 2023

paul-r-gall commented Feb 28, 2023

repokitteh-read-only bot commented Feb 28, 2023

mattklein123 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kyessenov left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

kyessenov left a comment

Choose a reason for hiding this comment

wbpcode left a comment

Choose a reason for hiding this comment

wbpcode commented Mar 10, 2023