Add ByteBufFormat option to LoggingHandler (#9915)

Motivation

LoggingHandler is a very useful tool for debugging and for tracking the
sequence of events in a pipeline. LoggingHandler also includes the
functionality to log a hex dump of all written and received ByteBufs.
This can be useful for small messages, but for large messages, this can
potentially result in extremely large logs. E.g., a 1 MB payload will
result in over a 1 MB log message being recorded. While LoggingHandler
may only be intended for debugging, this can still be too excessive in
some debugging scenarios.

Modifications

* Create a new ByteBufFormat enum that allows users to specify "SIMPLE"
or "HEX_DUMP" logging for ByteBufs.
* For all constructors that currently accept a LogLevel parameter,
create new overloaded constructors that also accept this enum as a
parameter.
* Continue to record hex dumps by default.

Result

Users will be able to opt out of full hex dump recording, if they wish
to.

handler/src/main/java/io/netty/handler/logging/ByteBufFormat.java

@@ -0,0 +1,36 @@
+/*
+ * Copyright 2020 The Netty Project
+ *
+ * The Netty Project licenses this file to you under the Apache License,
+ * version 2.0 (the "License"); you may not use this file except in compliance
+ * with the License. You may obtain a copy of the License at:
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations
+ * under the License.
+ */
+package io.netty.handler.logging;
+
+import io.netty.buffer.ByteBuf;
+import io.netty.buffer.ByteBufHolder;
+import io.netty.buffer.ByteBufUtil;
+
+/**
+ * Used to control the format and verbosity of logging for {@link ByteBuf}s and {@link ByteBufHolder}s.
+ *
+ * @see LoggingHandler
+ */
+public enum ByteBufFormat {
+    /**
+     * {@link ByteBuf}s will be logged in a simple format, with no hex dump included.
+     */
+    SIMPLE,
+    /**
+     * {@link ByteBuf}s will be logged using {@link ByteBufUtil#appendPrettyHexDump(StringBuilder, ByteBuf)}.
+     */
+    HEX_DUMP
+}

handler/src/main/java/io/netty/handler/logging/LoggingHandler.java

@@ -35,7 +35,7 @@ import static io.netty.util.internal.StringUtil.NEWLINE;
 
 /**
  * A {@link ChannelHandler} that logs all events using a logging framework.
- * By default, all events are logged at <tt>DEBUG</tt> level.
+ * By default, all events are logged at <tt>DEBUG</tt> level and full hex dumps are recorded for ByteBufs.
  */
 @Sharable
 @SuppressWarnings({ "StringConcatenationInsideStringBufferAppend", "StringBufferReplaceableByString" })
@@ -47,6 +47,7 @@ public class LoggingHandler extends ChannelDuplexHandler {
     protected final InternalLogLevel internalLevel;
 
     private final LogLevel level;
+    private final ByteBufFormat byteBufFormat;
 
     /**
      * Creates a new instance whose logger name is the fully qualified class
@@ -63,7 +64,19 @@ public class LoggingHandler extends ChannelDuplexHandler {
      * @param level the log level
      */
     public LoggingHandler(LogLevel level) {
+        this(level, ByteBufFormat.HEX_DUMP);
+    }
+
+    /**
+     * Creates a new instance whose logger name is the fully qualified class
+     * name of the instance.
+     *
+     * @param level the log level
+     * @param byteBufFormat the ByteBuf format
+     */
+    public LoggingHandler(LogLevel level, ByteBufFormat byteBufFormat) {
         this.level = ObjectUtil.checkNotNull(level, "level");
+        this.byteBufFormat = ObjectUtil.checkNotNull(byteBufFormat, "byteBufFormat");
         logger = InternalLoggerFactory.getInstance(getClass());
         internalLevel = level.toInternalLevel();
     }
@@ -85,8 +98,20 @@ public class LoggingHandler extends ChannelDuplexHandler {
      * @param level the log level
      */
     public LoggingHandler(Class<?> clazz, LogLevel level) {
+        this(clazz, level, ByteBufFormat.HEX_DUMP);
+    }
+
+    /**
+     * Creates a new instance with the specified logger name.
+     *
+     * @param clazz the class type to generate the logger for
+     * @param level the log level
+     * @param byteBufFormat the ByteBuf format
+     */
+    public LoggingHandler(Class<?> clazz, LogLevel level, ByteBufFormat byteBufFormat) {
         ObjectUtil.checkNotNull(clazz, "clazz");
         this.level = ObjectUtil.checkNotNull(level, "level");
+        this.byteBufFormat = ObjectUtil.checkNotNull(byteBufFormat, "byteBufFormat");
         logger = InternalLoggerFactory.getInstance(clazz);
         internalLevel = level.toInternalLevel();
     }
@@ -107,9 +132,21 @@ public class LoggingHandler extends ChannelDuplexHandler {
      * @param level the log level
      */
     public LoggingHandler(String name, LogLevel level) {
+        this(name, level, ByteBufFormat.HEX_DUMP);
+    }
+
+    /**
+     * Creates a new instance with the specified logger name.
+     *
+     * @param name the name of the class to use for the logger
+     * @param level the log level
+     * @param byteBufFormat the ByteBuf format
+     */
+    public LoggingHandler(String name, LogLevel level, ByteBufFormat byteBufFormat) {
         ObjectUtil.checkNotNull(name, "name");
 
         this.level = ObjectUtil.checkNotNull(level, "level");
+        this.byteBufFormat = ObjectUtil.checkNotNull(byteBufFormat, "byteBufFormat");
         logger = InternalLoggerFactory.getInstance(name);
         internalLevel = level.toInternalLevel();
     }
@@ -121,6 +158,13 @@ public class LoggingHandler extends ChannelDuplexHandler {
         return level;
     }
 
+    /**
+     * Returns the {@link ByteBufFormat} that this handler uses to log
+     */
+    public ByteBufFormat byteBufFormat() {
+        return byteBufFormat;
+    }
+
     @Override
     public void channelRegistered(ChannelHandlerContext ctx) throws Exception {
         if (logger.isEnabled(internalLevel)) {
@@ -306,7 +350,7 @@ public class LoggingHandler extends ChannelDuplexHandler {
     /**
      * Generates the default log message of the specified event whose argument is a {@link ByteBuf}.
      */
-    private static String formatByteBuf(ChannelHandlerContext ctx, String eventName, ByteBuf msg) {
+    private String formatByteBuf(ChannelHandlerContext ctx, String eventName, ByteBuf msg) {
         String chStr = ctx.channel().toString();
         int length = msg.readableBytes();
         if (length == 0) {
@@ -314,11 +358,18 @@ public class LoggingHandler extends ChannelDuplexHandler {
             buf.append(chStr).append(' ').append(eventName).append(": 0B");
             return buf.toString();
         } else {
-            int rows = length / 16 + (length % 15 == 0? 0 : 1) + 4;
+            int outputLength = chStr.length() + 1 + eventName.length() + 2 + 10 + 1;
-            StringBuilder buf = new StringBuilder(chStr.length() + 1 + eventName.length() + 2 + 10 + 1 + 2 + rows * 80);
+            if (byteBufFormat == ByteBufFormat.HEX_DUMP) {
-
+                int rows = length / 16 + (length % 15 == 0? 0 : 1) + 4;
-            buf.append(chStr).append(' ').append(eventName).append(": ").append(length).append('B').append(NEWLINE);
+                int hexDumpLength = 2 + rows * 80;
-            appendPrettyHexDump(buf, msg);
+                outputLength += hexDumpLength;
+            }
+            StringBuilder buf = new StringBuilder(outputLength);
+            buf.append(chStr).append(' ').append(eventName).append(": ").append(length).append('B');
+            if (byteBufFormat == ByteBufFormat.HEX_DUMP) {
+                buf.append(NEWLINE);
+                appendPrettyHexDump(buf, msg);
+            }
 
             return buf.toString();
         }
@@ -327,7 +378,7 @@ public class LoggingHandler extends ChannelDuplexHandler {
     /**
      * Generates the default log message of the specified event whose argument is a {@link ByteBufHolder}.
      */
-    private static String formatByteBufHolder(ChannelHandlerContext ctx, String eventName, ByteBufHolder msg) {
+    private String formatByteBufHolder(ChannelHandlerContext ctx, String eventName, ByteBufHolder msg) {
         String chStr = ctx.channel().toString();
         String msgStr = msg.toString();
         ByteBuf content = msg.content();
@@ -337,13 +388,19 @@ public class LoggingHandler extends ChannelDuplexHandler {
             buf.append(chStr).append(' ').append(eventName).append(", ").append(msgStr).append(", 0B");
             return buf.toString();
         } else {
-            int rows = length / 16 + (length % 15 == 0? 0 : 1) + 4;
+            int outputLength = chStr.length() + 1 + eventName.length() + 2 + msgStr.length() + 2 + 10 + 1;
-            StringBuilder buf = new StringBuilder(
+            if (byteBufFormat == ByteBufFormat.HEX_DUMP) {
-                    chStr.length() + 1 + eventName.length() + 2 + msgStr.length() + 2 + 10 + 1 + 2 + rows * 80);
+                int rows = length / 16 + (length % 15 == 0? 0 : 1) + 4;
-
+                int hexDumpLength = 2 + rows * 80;
+                outputLength += hexDumpLength;
+            }
+            StringBuilder buf = new StringBuilder(outputLength);
             buf.append(chStr).append(' ').append(eventName).append(": ")
-               .append(msgStr).append(", ").append(length).append('B').append(NEWLINE);
+               .append(msgStr).append(", ").append(length).append('B');
-            appendPrettyHexDump(buf, content);
+            if (byteBufFormat == ByteBufFormat.HEX_DUMP) {
+                buf.append(NEWLINE);
+                appendPrettyHexDump(buf, content);
+            }
 
             return buf.toString();
         }

handler/src/test/java/io/netty/handler/logging/LoggingHandlerTest.java

@@ -39,6 +39,7 @@ import java.util.ArrayList;
 import java.util.Iterator;
 import java.util.List;
 
+import static io.netty.util.internal.StringUtil.NEWLINE;
 import static org.hamcrest.CoreMatchers.is;
 import static org.hamcrest.CoreMatchers.nullValue;
 import static org.hamcrest.CoreMatchers.sameInstance;
@@ -217,7 +218,20 @@ public class LoggingHandlerTest {
         ByteBuf msg = Unpooled.copiedBuffer("hello", CharsetUtil.UTF_8);
         EmbeddedChannel channel = new EmbeddedChannel(new LoggingHandler());
         channel.writeInbound(msg);
-        verify(appender).doAppend(argThat(new RegexLogMatcher(".+READ: " + msg.readableBytes() + "B$")));
+        verify(appender).doAppend(argThat(new RegexLogMatcher(".+READ: " + msg.readableBytes() + "B$", true)));
+
+        ByteBuf handledMsg = channel.readInbound();
+        assertThat(msg, is(sameInstance(handledMsg)));
+        handledMsg.release();
+        assertThat(channel.readInbound(), is(nullValue()));
+    }
+
+    @Test
+    public void shouldLogByteBufDataReadWithSimpleFormat() throws Exception {
+        ByteBuf msg = Unpooled.copiedBuffer("hello", CharsetUtil.UTF_8);
+        EmbeddedChannel channel = new EmbeddedChannel(new LoggingHandler(LogLevel.DEBUG, ByteBufFormat.SIMPLE));
+        channel.writeInbound(msg);
+        verify(appender).doAppend(argThat(new RegexLogMatcher(".+READ: " + msg.readableBytes() + "B$", false)));
 
         ByteBuf handledMsg = channel.readInbound();
         assertThat(msg, is(sameInstance(handledMsg)));
@@ -230,7 +244,7 @@ public class LoggingHandlerTest {
         ByteBuf msg = Unpooled.EMPTY_BUFFER;
         EmbeddedChannel channel = new EmbeddedChannel(new LoggingHandler());
         channel.writeInbound(msg);
-        verify(appender).doAppend(argThat(new RegexLogMatcher(".+READ: 0B$")));
+        verify(appender).doAppend(argThat(new RegexLogMatcher(".+READ: 0B$", false)));
 
         ByteBuf handledMsg = channel.readInbound();
         assertThat(msg, is(sameInstance(handledMsg)));
@@ -248,7 +262,7 @@ public class LoggingHandlerTest {
 
         EmbeddedChannel channel = new EmbeddedChannel(new LoggingHandler());
         channel.writeInbound(msg);
-        verify(appender).doAppend(argThat(new RegexLogMatcher(".+READ: foobar, 5B$")));
+        verify(appender).doAppend(argThat(new RegexLogMatcher(".+READ: foobar, 5B$", true)));
 
         ByteBufHolder handledMsg = channel.readInbound();
         assertThat(msg, is(sameInstance(handledMsg)));
@@ -270,10 +284,16 @@ public class LoggingHandlerTest {
     private static final class RegexLogMatcher implements ArgumentMatcher<ILoggingEvent> {
 
         private final String expected;
+        private final boolean shouldContainNewline;
         private String actualMsg;
 
         RegexLogMatcher(String expected) {
+            this(expected, false);
+        }
+
+        RegexLogMatcher(String expected, boolean shouldContainNewline) {
             this.expected = expected;
+            this.shouldContainNewline = shouldContainNewline;
         }
 
         @Override
@@ -281,7 +301,11 @@ public class LoggingHandlerTest {
         public boolean matches(ILoggingEvent actual) {
             // Match only the first line to skip the validation of hex-dump format.
             actualMsg = actual.getMessage().split("(?s)[\\r\\n]+")[0];
-            return actualMsg.matches(expected);
+            if (actualMsg.matches(expected)) {
+                // The presence of a newline implies a hex-dump was logged
+                return actual.getMessage().contains(NEWLINE) == shouldContainNewline;
+            }
+            return false;
         }
     }