Set the correct log level for wire logging and h2 frame logging #1123

Scottmitch · 2020-08-12T01:58:28Z

Motivation:
When enableWireLogging and h2 frameLogger are set on the builder we
always log at TRACE level regardless of what level the logging
configuration specifies. The h2 frameLogger has conditional logic which
limits the amount of data logged for levels less than TRACE, and it is
generally unexpected to log at a different level than configured by the
user.

Modifications:

When Http2FrameLogger and LoggingHandler are created we should get the
log level from SL4J and pass the translated Netty LogLevel upon
construction

Result:
Debug logging uses the same log level as configured by the user.

...t-netty-internal/src/main/java/io/servicetalk/transport/netty/internal/NettyLoggerUtils.java

idelpivnitskiy

👍

...t-netty-internal/src/main/java/io/servicetalk/transport/netty/internal/NettyLoggerUtils.java

NiteshKant · 2020-08-12T21:42:49Z

...t-netty-internal/src/main/java/io/servicetalk/transport/netty/internal/NettyLoggerUtils.java

+     * @param loggerName The logger name to lookup.
+     * @return Netty's {@link LogLevel} corresponding to the SL4J log level for {@code loggerName}.
+     */
+    public static LogLevel getNettyLogLevel(String loggerName) {


A behavior that is useful is to enable wire logging in code but disable it using logger levels. I think this will always enable wire logging if it is enabled in code, is that correct?

Good question! Most of the logger implementations also support OFF that disables logging [1, 2] from the logger config. But we need to adjust getNettyLogLevel method to support it.

https://logging.apache.org/log4j/2.x/log4j-api/apidocs/org/apache/logging/log4j/Level.html#OFF

http://logback.qos.ch/apidocs/ch/qos/logback/classic/Level.html#OFF

The configuration can be modified to accommodate this, an appender can include a threshold level. I will enhance our test log4j2-test.xml to accommodate this.

I am not sure I am following the motivation now. Threshold filter is specific to log4j, so not ideal that we have to depend on that for the expected behavior.

Why not just let the user specify the level at which they want to log?

Threshold filter was one example of how this can be handled in configuration, setting the logging value to OFF is another example. Specifying the log level programmatically requires additional API surface area (e.g. log level API, propagation of log level) which seems redundant if the configuration has to be setup correctly to enable/disable the logger anyways. This change still allows for specifying the logger in builder code and disable it via config, which I think was your initial concern?

...t-netty-internal/src/main/java/io/servicetalk/transport/netty/internal/NettyLoggerUtils.java

Motivation: When enableWireLogging and h2 frameLogger are set on the builder we always log at TRACE level regardless of what level the logging configuration specifies. The h2 frameLogger has conditional logic which limits the amount of data logged for levels less than TRACE, and it is generally unexpected to log at a different level than configured by the user. Modifications: - When Http2FrameLogger and LoggingHandler are created we should get the log level from SL4J and pass the translated Netty LogLevel upon construction Result: Debug logging uses the same log level as configured by the user.

Scottmitch · 2020-08-27T18:34:04Z

servicetalk-examples/grpc/helloworld/src/main/resources/log4j2.xml

@@ -21,14 +21,6 @@
    </Console>
  </Appenders>
  <Loggers>
-    <!--
-        This is an example of how to configure logging of wire events:
-          1. Add a Logger with `TRACE` level;


since there is no more strict requirement on the log level, we have an opportunity to simplify the examples. Log4j can be configured in many ways (filters, multiple appenders, using different loggers, etc.) and I don't think this is central to understanding servicetalk.

idelpivnitskiy

👍
Like new approach. It gives more flexibility. For example, in tests we don't need to worry about removing enableWireLogging before committing changes (always was the pain) because the wire logger is off by default and controlled by system property.

NiteshKant · 2020-09-10T16:46:27Z

...y-internal/src/main/java/io/servicetalk/transport/netty/internal/WireLoggingInitializer.java

@@ -34,11 +37,14 @@
     * @param loggerName The name of the logger to log wire events.
     */
    public WireLoggingInitializer(final String loggerName) {
-        loggingHandler = new LoggingHandler(loggerName, TRACE);
+        LogLevel logLevel = getNettyLogLevel(loggerName);
+        loggingHandler = logLevel != null ? new LoggingHandler(loggerName, logLevel) : null;


Just a suggestion; feel free to ignore.

This approach precludes dynamic log level manipulation for existing channels. I think we should always add the handler if user opts-in to it using the builder setting.

logLevel == null will only if the logging level can't be mapped to a Netty LogLevel (e.g. "OFF"). The user's logging config can set the logging level set to a valid level (e.g. not "OFF") and use a filter to achieve the dynamic enable/disable of logs on pre-existing channels.

Motivation: Wire logger and h2 frame logger are controlled by the logger configuration after apple#1123. It allows us to use these logger names in tests and enabled them via system property when required for local debugging. Having 2 different logger names for client and server controlled by a single system property does not help much. We can use thread name to understand if a logger statement belongs to a client or to a server. A single logger name simplifies usage in tests. Modifications: - Keep only a single `servicetalk-tests-wire-logger` logger name; - Add `servicetalk-tests-h2-frame-logger` logger name and `servicetalk.logger.h2FrameLogLevel` system property to control visibility for h2 frames; - Update all tests to use new names; Result: Separate system property to control wire logger and h2 frame logger.

Motivation: Wire logger and h2 frame logger are controlled by the logger configuration after #1123. It allows us to use these logger names in tests and enabled them via system property when required for local debugging. Having 2 different logger names for client and server controlled by a single system property does not help much. We can use thread name to understand if a logger statement belongs to a client or to a server. A single logger name simplifies usage in tests. Modifications: - Keep only a single `servicetalk-tests-wire-logger` logger name; - Add `servicetalk-tests-h2-frame-logger` logger name and `servicetalk.logger.h2FrameLogLevel` system property to control visibility for h2 frames; - Update all tests to use new names; Result: Separate system property to control wire logger and h2 frame logger.

Scottmitch requested review from NiteshKant and idelpivnitskiy August 12, 2020 01:58

Scottmitch commented Aug 12, 2020

View reviewed changes

...t-netty-internal/src/main/java/io/servicetalk/transport/netty/internal/NettyLoggerUtils.java Show resolved Hide resolved

idelpivnitskiy approved these changes Aug 12, 2020

View reviewed changes

...t-netty-internal/src/main/java/io/servicetalk/transport/netty/internal/NettyLoggerUtils.java Show resolved Hide resolved

NiteshKant reviewed Aug 12, 2020

View reviewed changes

idelpivnitskiy requested changes Aug 27, 2020

View reviewed changes

...t-netty-internal/src/main/java/io/servicetalk/transport/netty/internal/NettyLoggerUtils.java Outdated Show resolved Hide resolved

Scottmitch added 2 commits August 27, 2020 10:45

modify logging config

8894e33

Scottmitch force-pushed the logger_level branch from 52a6888 to 8894e33 Compare August 27, 2020 18:21

add support for unmapped LogLevels

f664758

Scottmitch commented Aug 27, 2020

View reviewed changes

Scottmitch requested review from idelpivnitskiy and NiteshKant August 27, 2020 18:35

switch from ThresholdFilter to log level OFF

42dcd11

idelpivnitskiy approved these changes Sep 10, 2020

View reviewed changes

NiteshKant approved these changes Sep 10, 2020

View reviewed changes

Scottmitch merged commit 26b4f60 into apple:main Sep 11, 2020

Scottmitch deleted the logger_level branch September 11, 2020 02:14

idelpivnitskiy mentioned this pull request Oct 14, 2020

Improve servicetalk-test-resources/log4j2.xml #1181

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Set the correct log level for wire logging and h2 frame logging #1123

Set the correct log level for wire logging and h2 frame logging #1123

Scottmitch commented Aug 12, 2020

idelpivnitskiy left a comment

NiteshKant Aug 12, 2020

idelpivnitskiy Aug 27, 2020

Scottmitch Aug 27, 2020

NiteshKant Aug 27, 2020

Scottmitch Sep 10, 2020 •

edited

Loading

Scottmitch Aug 27, 2020

idelpivnitskiy left a comment

NiteshKant Sep 10, 2020

Scottmitch Sep 11, 2020

Set the correct log level for wire logging and h2 frame logging #1123

Set the correct log level for wire logging and h2 frame logging #1123

Conversation

Scottmitch commented Aug 12, 2020

idelpivnitskiy left a comment

Choose a reason for hiding this comment

NiteshKant Aug 12, 2020

Choose a reason for hiding this comment

idelpivnitskiy Aug 27, 2020

Choose a reason for hiding this comment

Scottmitch Aug 27, 2020

Choose a reason for hiding this comment

NiteshKant Aug 27, 2020

Choose a reason for hiding this comment

Scottmitch Sep 10, 2020 • edited Loading

Choose a reason for hiding this comment

Scottmitch Aug 27, 2020

Choose a reason for hiding this comment

idelpivnitskiy left a comment

Choose a reason for hiding this comment

NiteshKant Sep 10, 2020

Choose a reason for hiding this comment

Scottmitch Sep 11, 2020

Choose a reason for hiding this comment

Scottmitch Sep 10, 2020 •

edited

Loading