XDS Connection closure smart logging by mandarjog · Pull Request #14616 · envoyproxy/envoy

mandarjog · 2021-01-09T03:48:31Z

XDS connection closures are logged as warnings only for
repeated failures for certain type of status codes.

Signed-off-by: Mandar U Jog mjog@google.com

Will follow up with tests if this approach is ok.

XDS connection closures are logged as warnings only for repeated failures for certain type of status codes. Signed-off-by: Mandar U Jog <mjog@google.com>

htuch

Thanks; @mandarjog can you add tests for all these new behaviors? There's a lot of different branch conditions, so we should have some coverage of the logic here.
/wait

source/common/config/grpc_stream.h

htuch · 2021-01-11T16:24:43Z

source/common/config/grpc_stream.h

    stream_ = async_client_->start(service_method_, *this, Http::AsyncClient::StreamOptions());
    if (stream_ == nullptr) {
-      ENVOY_LOG(warn, "Unable to establish new stream");
+      ENVOY_LOG(debug, "Unable to establish new grpc config stream");


Shouldn't this be a warning? There's a real failure ocurring.

The real failure with error message is recorded in the call back. I don;t think there is a case where something is not recorded in the callback, but is recorded here. This is also the source of noise since it does not tell the reason.

htuch · 2021-01-11T16:25:10Z

source/common/config/grpc_stream.h

  void onReceiveMessage(ResponseProtoPtr<ResponseProto>&& message) override {
    // Reset here so that it starts with fresh backoff interval on next disconnect.
    backoff_strategy_->reset();
+    unsetFailure();


Why is this needed? Isn't it sufficient to unset on successful connect?

It is the comment on the next line that lead me to believe I need a reset here, to.
But I think it makes sense to remove it. ack.

howardjohn · 2021-01-11T17:00:47Z

A release note may be nice, as this will impact everyone's logs

howardjohn

I am not sure masking errors to debug level is the right approach.

Moving status code 0 to debug level makes sense to me, but I think we want to see errors?

Signed-off-by: Mandar U Jog <mjog@google.com>

howardjohn · 2021-01-12T15:58:18Z

I wasn't sure from the code, do we log the first error?

XDS Failed 0
XDS Failed 1
XDS Failed 2
XDS Failed 3
XDS connected

For example, in the above ^, do we log the failure 3 or failure 0?

In my opinion, logging the first failure is ideal, because if we have a log on first failure and successful connections, then we know that everything between failure 0 and "connected" is more failures, even if they are not explicitly logged. if we log only latter failures we may miss when the issues first start.

mandarjog · 2021-01-12T16:17:46Z

@htuch can you point me to an example of faking time ?

mandarjog · 2021-01-12T17:17:39Z

If xds reconnected in the allotted time, then we do not log anything. ( there is no connection successful message yet)

at debug level, we log every event.

If the connection does not recover in allotted time, we will print the original error and state the amount of time this condition has been going on.

htuch · 2021-01-13T02:15:17Z

@mandarjog you want a fake time source for the dispatcher, see the MockDispatcher GlobalTimeSystem. You probably want to return a SimulatedTimeSystem or MockTimeSystem instead.

Signed-off-by: Mandar U Jog <mjog@google.com>

mandarjog · 2021-01-13T08:38:51Z

precheck deps succeeds locally bazel query 'deps(//source/exe:envoy_main_common_with_core_extensions_lib)' for me.

mandarjog · 2021-01-14T00:08:36Z

I am thinking of adding and INFO message on successful connection, and it will also state how long was it disconnected.
onReceiveMessage seems like a positive sign that we are connected to the controlplane, more so than
async_client_->start(service_method_, *this, Http::AsyncClient::StreamOptions()) != nullptr. @PiotrSikora @htuch ?

htuch · 2021-01-14T00:11:19Z

Sounds reasonable, this is a pretty important diagnostic that applies to many use cases. We can always drop log level if folks find it too spammy.

github-actions · 2021-03-09T04:03:21Z

This pull request has been automatically marked as stale because it has not had activity in the last 30 days. It will be closed in 7 days if no further activity occurs. Please feel free to give a status update now, ping for review, or re-open when it's ready. Thank you for your contributions!

github-actions · 2021-03-16T04:03:31Z

This pull request has been automatically closed because it has not had activity in the last 37 days. Please feel free to give a status update now, ping for review, or re-open when it's ready. Thank you for your contributions!

mandarjog force-pushed the config_noise branch 2 times, most recently from bd2d53d to 49c88ac Compare January 9, 2021 05:26

XDS Connection closure smart logging

98e6f69

XDS connection closures are logged as warnings only for repeated failures for certain type of status codes. Signed-off-by: Mandar U Jog <mjog@google.com>

mandarjog force-pushed the config_noise branch from 49c88ac to 98e6f69 Compare January 10, 2021 08:27

htuch suggested changes Jan 11, 2021

View reviewed changes

repokitteh-read-only bot added the waiting label Jan 11, 2021

htuch self-assigned this Jan 11, 2021

htuch requested a review from ramaraochavali January 11, 2021 16:28

howardjohn mentioned this pull request Jan 11, 2021

reduce xds proxy log noise istio/istio#29959

Merged

howardjohn reviewed Jan 11, 2021

View reviewed changes

howardjohn mentioned this pull request Jan 11, 2021

Another attempt at xds proxy log cleanup istio/istio#29975

Merged

change to absl:optional

6bc887b

Signed-off-by: Mandar U Jog <mjog@google.com>

repokitteh-read-only bot removed the waiting label Jan 12, 2021

Add unit tests

a35ab2c

Signed-off-by: Mandar U Jog <mjog@google.com>

Base automatically changed from master to main January 15, 2021 23:02

htuch added the waiting label Feb 7, 2021

github-actions bot added the stale stalebot believes this issue/PR has not been touched recently label Mar 9, 2021

github-actions bot closed this Mar 16, 2021

tbarrella mentioned this pull request Jul 7, 2021

Reduce warning - grpc Config Stream closed: 14 noise #14591

Closed

tbarrella mentioned this pull request Jul 19, 2021

grpc stream: reduce log level depending on remote close status #17300

Merged

Conversation

mandarjog commented Jan 9, 2021

Uh oh!

htuch left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

htuch Jan 11, 2021

Choose a reason for hiding this comment

Uh oh!

mandarjog Jan 11, 2021

Choose a reason for hiding this comment

Uh oh!

htuch Jan 11, 2021

Choose a reason for hiding this comment

Uh oh!

mandarjog Jan 11, 2021

Choose a reason for hiding this comment

Uh oh!

howardjohn commented Jan 11, 2021

Uh oh!

howardjohn left a comment

Choose a reason for hiding this comment

Uh oh!

howardjohn commented Jan 12, 2021

Uh oh!

mandarjog commented Jan 12, 2021

Uh oh!

mandarjog commented Jan 12, 2021

Uh oh!

htuch commented Jan 13, 2021

Uh oh!

mandarjog commented Jan 13, 2021

Uh oh!

mandarjog commented Jan 14, 2021

Uh oh!

htuch commented Jan 14, 2021

Uh oh!

github-actions bot commented Mar 9, 2021

Uh oh!

github-actions bot commented Mar 16, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants