core: ChannelLogger by zhangkun83 · Pull Request #5024 · grpc/grpc-java

zhangkun83 · 2018-11-02T18:10:51Z

Introduce ChannelLogger, which is a utility provided to LoadBalancer implementations (potentially NameResolvers too) for recording events to channel trace. This is immediately required by client-side health checking (#4932, https://github.com/grpc/proposal/blob/master/A17-client-side-health-checking.md) to record an error about disabling health checking. It is also useful for any LoadBalancer implementations to record important information.

ChannelLogger implementation is backed by the internal ChannelTracer/Channelz. Because Channelz limits the number of retained events, and events are lost once the process ends, I have expanded it to also log Java logger. This would provide a "last resort" in cases where there are too many events or off-line investigation is needed. All logs are prefixed with logId so that they can be easily associated with the involved Channel/Subchannel.

To prevent log spamming, the logs are all at FINE level or below so that they are not visible by default. They are logged to ChannelLogger's logger, so that user can have precise control.

There are also more verbose information that may not fit in ChannelTracer, but can be useful for debugging. It's desirable that these logs are associated with logId, but they currently manually include the logId, which is cumbersome and may result in inconsistency. For this use case, I added the DEBUG level for ChannelLogger, which formats the log in the same way as other levels, while not recorded to Channelz.

I have converted most logging and channel tracer recording in the Channel implementation and LoadBalancers.

…GrpclbState's logs

carl-mastrangelo · 2018-11-02T20:59:10Z

+ * A Channel-specific logger provided by GRPC library to {@link LoadBalancer} implementations.
+ * Information logged here goes to <string>Channelz</strong>, and to Java logger as well.
+ */
+public abstract class ChannelLogger {


is this threadsafe?

Yes. Added annotation.

carl-mastrangelo · 2018-11-02T21:02:09Z

+   * +---------------------+-------------------+-------------------+
+   * | ChannelLogger Level | Channelz Severity | Java Logger Level |
+   * +---------------------+-------------------+-------------------+
+   * | DEBUG               | N/A               | FINEST            |


This table should be encoded as arguments to the enum valuies:

public enum Level { DEBUG(null, "CT_INFO", Level.FINEST), }

That way the mapping can be without a switch statement below.

I actually need to reference the CT_INFO enum to make this useful and robust, but it's internal API and I don't see how I can do it without exposing it.

It's suffiicient to make this a String instead of a hard ref, and then have a test that assert they all work.

For these fields to be accessible from ChannelLoggerImpl, they would need to be public, which technically exposes these CT_ enums even not referencing them directly. Doesn't seem enough benefit from doing that.

These could be exposed via an internal accessor.

The benefit is that we can use hard references to see exactly how they map, rather than relying on switch statements.

carl-mastrangelo · 2018-11-02T21:03:14Z

-      }
-    };
+  ChannelTracer(
+      InternalLogId logId, final int maxEvents, long channelCreationTimeNanos, String description) {


You should document the behavior change of maxEvents

carl-mastrangelo · 2018-11-02T21:03:43Z

-        return super.add(event);
-      }
-    };
+  ChannelTracer(


Can description be null?

No one is passing null, so I just added the null check.

carl-mastrangelo · 2018-11-02T21:06:06Z

+   * +---------------------+-------------------+-------------------+
+   * </pre>
+   */
+  public enum Level {


This probably deserves a name like ChannelLevel, since it behaves differently than other "Levels".

Renamed to ChannelLogLevel.

ejona86 · 2018-11-02T23:11:12Z

 import io.grpc.Attributes;
 import io.grpc.CallOptions;
+import io.grpc.ChannelLogger;
+import io.grpc.ChannelLogger.Level;


I'd suggest not importing this and always referencing it via ChannelLogger.Level. Otherwise it is pretty confusing and you can't import java.util.logging.Level.

As suggested by @carl-mastrangelo, I have renamed Level to ChannelLogLevel so there is no collision.

ejona86 · 2018-11-02T23:12:49Z

  void propagateError(Status status) {
-    logger.log(Level.FINE, "[{0}] Had an error: {1}; dropList={2}; backendList={3}",
-        new Object[] {logId, status, dropList, backendList});
+    logger.log(Level.DEBUG, "Error: " + status);


We really want to know whether or not this log message will be used, to avoid the string handling when useless.

Since ChannelLogger is not on data path and is called pretty infrequently, I am not sure it's worth the code clutter to wrap it with a check.

Things like logger.log(Level.DEBUG, "Got an LB response: " + response); could still be large and run on the network thread. Also, some LBs may do RPCs on cache misses, which could want to log to DEBUG.

I'm a bit worried about how much is getting pulled into this API. There's a lot of data being logged. Like every time the picker changes with logger.log(Level.INFO, state + ": picks=" + picker.pickList + ", drops=" + picker.dropList);. I know that isn't on the critical path, but that still happens frequently. And most of the time nobody will see it.

What about log(Level level, String template, Object... args)?. For now I can check the loggable level in the implementation and that would save the string generation for DEBUG. We could optimize ChannelTracer even later to generate strings only when Channelz is requested.

log(Level, String, Object...) seems fine to me. It'd probably be an overload (so log(Level, String) would still exist) to avoid allocating the Object[] when unnecessary.

…neration for DEBUG if not logged.

carl-mastrangelo · 2018-11-05T23:21:58Z

+   * Logs a message, using a message template and a list of arguments used to generate the log
+   * message with {@link String#format}.
+   */
+  public abstract void log(ChannelLogLevel level, String template, Object... args);


Isn't this format different than what normal loggers use? (i.e. {}) ?

I think this should be something that fits in with other, similar log statements. (I.e. it should do what SimpleFormatter does)

It should use MessageFormat.

Used MessageFormat. PTAL.

…trace

ejona86 · 2018-11-06T23:45:03Z

+        tracer.logOnly(Level.FINEST, MessageFormat.format(messageFormat, args));
+      }
+    } else {
+      reportToTracer(level, MessageFormat.format(messageFormat, args));


This will create the event and format the message even when tracing is disabled.

zhangkun83 added 6 commits October 31, 2018 18:17

WIP: ChannelLogger

7913866

All test fixed. Polished documentation

75628de

Test that ChannelTracer also logs

4383dff

WIP: Add DEBUG level that doesn't go to ChannelTracer; re-organizing …

63482b1

…GrpclbState's logs

All tests pass

56bac65

Test for ChannelLoggerImpl

78f1eb7

zhangkun83 requested review from carl-mastrangelo, dapengzhang0 and ejona86 November 2, 2018 18:10

carl-mastrangelo reviewed Nov 2, 2018

View reviewed changes

ejona86 reviewed Nov 2, 2018

View reviewed changes

zhangkun83 added 2 commits November 5, 2018 11:07

Rename Level to ChannelLogLevel; Add formatter method and skip log ge…

6c4c62f

…neration for DEBUG if not logged.

Address the rest of comments

eaa6f38

carl-mastrangelo reviewed Nov 5, 2018

View reviewed changes

zhangkun83 added 2 commits November 6, 2018 09:45

Use MessageFormat

367641c

Merge remote-tracking branch 'upstream/master' into lb_helper_record_…

c204289

…trace

ejona86 approved these changes Nov 6, 2018

View reviewed changes

Skip generating Event if trace is disabled

f97b4ee

zhangkun83 merged commit 6b48eb4 into grpc:master Nov 7, 2018

zhangkun83 deleted the lb_helper_record_trace branch November 7, 2018 00:48

lock Bot locked as resolved and limited conversation to collaborators Feb 5, 2019

Uh oh!

Conversation

zhangkun83 commented Nov 2, 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!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants