ISPN-8704 Hot Rod Access Log fixes

- Use MDC
infinispan · Jan 30, 2018 · d691b08 · d691b08
1 parent d999103
commit d691b08
Show file tree

Hide file tree

Showing 4 changed files with 96 additions and 30 deletions.
diff --git a/...hotrod/src/main/java/org/infinispan/server/hotrod/logging/HotRodAccessLoggingHandler.java b/...hotrod/src/main/java/org/infinispan/server/hotrod/logging/HotRodAccessLoggingHandler.java
@@ -1,12 +1,17 @@
 package org.infinispan.server.hotrod.logging;
 
-import java.time.LocalDateTime;
+import java.net.InetSocketAddress;
+import java.time.ZonedDateTime;
 import java.time.temporal.ChronoUnit;
+import java.time.temporal.Temporal;
 
-import org.infinispan.commons.logging.LogFactory;
 import org.infinispan.commons.util.Util;
 import org.infinispan.server.hotrod.CacheDecodeContext;
 import org.infinispan.server.hotrod.HotRodOperation;
+import org.infinispan.server.hotrod.HotRodVersion;
+import org.infinispan.util.logging.LogFactory;
+import org.jboss.logging.Logger;
+import org.jboss.logging.MDC;
 
 import io.netty.buffer.ByteBuf;
 import io.netty.buffer.ByteBufHolder;
@@ -15,33 +20,37 @@
 import io.netty.channel.ChannelPromise;
 
 /**
- * Logging handler for hotrod to log what requests have come into the server
+ * Logging handler for Hot Rod to log what requests have come into the server
  *
  * @author wburns
  * @since 9.0
  */
 public class HotRodAccessLoggingHandler extends ChannelDuplexHandler {
-   private static final Log log = LogFactory.getLog(HotRodAccessLoggingHandler.class, Log.class);
+   private final static Logger log = LogFactory.getLogger("HOTROD_ACCESS_LOG");
 
-   LocalDateTime startTime;
+   Temporal when;
-   private int bytesRead = 0;
+   private int requestSize = 0;
+
+   public static boolean isEnabled() {
+      return log.isTraceEnabled();
+   }
 
    @Override
    public void channelRead(ChannelHandlerContext ctx, Object msg) throws Exception {
-      if (startTime == null) {
+      if (when == null) {
-         startTime = LocalDateTime.now();
+         when = ZonedDateTime.now();
       }
-      bytesRead += getByteSize(msg);
+      requestSize += getByteSize(msg);
 
       // Make sure we don't have a decode context between requests
-      ctx.channel().attr(LoggingContextHandler.DECODE_CONTEXT_KEY).remove();
+      ctx.channel().attr(LoggingContextHandler.DECODE_CONTEXT_KEY).set(null);
 
       super.channelRead(ctx, msg);
    }
 
    @Override
    public void write(ChannelHandlerContext ctx, Object msg, ChannelPromise promise) throws Exception {
-      if (startTime != null) {
+      if (when != null) {
          // We need the information from the context now, because we could clear the context soon after the write completes
          CacheDecodeContext cacheDecodeContext = ctx.channel().attr(LoggingContextHandler.DECODE_CONTEXT_KEY).get();
 
@@ -50,45 +59,58 @@ public void write(ChannelHandlerContext ctx, Object msg, ChannelPromise promise)
          String status;
          String exception = ctx.channel().attr(LoggingContextHandler.EXCEPTION_MESSAGE_KEY).get();
          byte[] key;
+         String who;
+         HotRodVersion version;
          // This is only null if an exception was thrown before we could decode a proper message
          if (cacheDecodeContext != null && exception == null) {
             // Method
             op = cacheDecodeContext.getHeader().getOp();
+            version = HotRodVersion.forVersion(cacheDecodeContext.getHeader().getVersion());
             key = cacheDecodeContext.getKey();
             // Cache name
             cacheName = cacheDecodeContext.getHeader().getCacheName();
             status = "OK";
+            who = cacheDecodeContext.getPrincipalName();
          } else {
             op = ctx.channel().attr(LoggingContextHandler.OPERATION_KEY).get();
             key = null;
             cacheName = ctx.channel().attr(LoggingContextHandler.CACHE_NAME_KEY).get();
             status = exception;
+            version = HotRodVersion.UNKNOWN;
+            who = null;
          }
 
          // IP
-         String remoteAddress = ctx.channel().remoteAddress().toString();
+         String remoteAddress = ((InetSocketAddress)ctx.channel().remoteAddress()).getHostString();
          // Date of first byte read
-         LocalDateTime startTime = this.startTime;
+         Temporal startTime = this.when;
-         this.startTime = null;
+         this.when = null;
 
          // Request Length
-         int bytesRead = this.bytesRead;
+         int requestSize = this.requestSize;
-         this.bytesRead = 0;
+         this.requestSize = 0;
 
          // Response Length - We rely on the fact that our encoder encodes the entire response in 1 write method
-         int bytesWritten = getByteSize(msg);
+         int responseSize = getByteSize(msg);
 
          super.write(ctx, msg, promise.addListener(f -> {
             // Duration
-            long ms;
+            long duration;
             if (startTime == null) {
-               ms = -1;
+               duration = -1;
             } else {
-               ms = ChronoUnit.MILLIS.between(startTime, LocalDateTime.now());
+               duration = ChronoUnit.MILLIS.between(startTime, ZonedDateTime.now());
             }
-            log.tracef("%s [%s] \"%s %s\" \"%s\" %s %d %d %d ms", remoteAddress,
+            MDC.clear();
-                  checkForNull(startTime), checkForNull(op), checkForNull(cacheName),
+            MDC.put("address", remoteAddress);
-                  status, checkForNull(key), bytesRead, bytesWritten, ms);
+            MDC.put("user", checkForNull(who));
+            MDC.put("method", checkForNull(op));
+            MDC.put("protocol", checkForNull(version));
+            MDC.put("status", checkForNull(status));
+            MDC.put("responseSize", responseSize);
+            MDC.put("requestSize", requestSize);
+            MDC.put("duration", duration);
+            log.tracef("/%s/%s", checkForNull(cacheName), checkForNull(key));
          }));
       } else {
          super.write(ctx, msg, promise);

diff --git a/...hotrod/src/main/java/org/infinispan/server/hotrod/transport/HotRodChannelInitializer.java b/...hotrod/src/main/java/org/infinispan/server/hotrod/transport/HotRodChannelInitializer.java
@@ -2,7 +2,6 @@
 
 import java.util.concurrent.ExecutorService;
 
-import org.infinispan.commons.logging.LogFactory;
 import org.infinispan.server.core.transport.NettyChannelInitializer;
 import org.infinispan.server.core.transport.NettyTransport;
 import org.infinispan.server.hotrod.AuthenticationHandler;
@@ -11,7 +10,6 @@
 import org.infinispan.server.hotrod.HotRodServer;
 import org.infinispan.server.hotrod.LocalContextHandler;
 import org.infinispan.server.hotrod.logging.HotRodAccessLoggingHandler;
-import org.infinispan.server.hotrod.logging.Log;
 import org.infinispan.server.hotrod.logging.LoggingContextHandler;
 
 import io.netty.channel.Channel;
@@ -52,7 +50,7 @@ public void initializeChannel(Channel ch) throws Exception {
       ch.pipeline().addLast("exception", new HotRodExceptionHandler());
 
       // Logging handlers
-      if (LogFactory.getLog(HotRodAccessLoggingHandler.class, Log.class).isTraceEnabled()) {
+      if (HotRodAccessLoggingHandler.isEnabled()) {
          ch.pipeline().addBefore("decoder", "logging", new HotRodAccessLoggingHandler());
          ch.pipeline().addAfter("encoder", "logging-context", LoggingContextHandler.getInstance());
       }

diff --git a/...er/hotrod/src/test/java/org/infinispan/server/hotrod/logging/HotRodAccessLoggingTest.java b/...er/hotrod/src/test/java/org/infinispan/server/hotrod/logging/HotRodAccessLoggingTest.java
@@ -0,0 +1,43 @@
+package org.infinispan.server.hotrod.logging;
+
+import static org.testng.AssertJUnit.assertTrue;
+
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.core.layout.PatternLayout;
+import org.infinispan.commons.test.skip.StringLogAppender;
+import org.infinispan.server.hotrod.test.HotRodSingleNodeTest;
+import org.testng.annotations.Test;
+
+/**
+ * @since 9.2
+ */
+@Test(groups = "functional", testName = "server.hotrod.logging.HotRodAccessLoggingTest")
+public class HotRodAccessLoggingTest extends HotRodSingleNodeTest {
+   public static final String LOG_FORMAT = "%X{address} %X{user} [%d{dd/MMM/yyyy:HH:mm:ss z}] \"%X{method} %m %X{protocol}\" %X{status} %X{requestSize} %X{responseSize} %X{duration}";
+   StringLogAppender logAppender;
+
+   @Override
+   protected void setup() throws Exception {
+      logAppender = new StringLogAppender("org.infinispan.HOTROD_ACCESS_LOG",
+            Level.TRACE,
+            t -> t.getName().startsWith("HotRod-HotRodAccessLoggingTest-ServerWorker"),
+            PatternLayout.newBuilder().withPattern(LOG_FORMAT).build());
+      logAppender.install();
+      super.setup();
+   }
+
+   @Override
+   protected void teardown() {
+      logAppender.uninstall();
+      super.teardown();
+   }
+
+   public void testHotRodAccessLog() {
+      client().put("key", "value");
+
+      server().getTransport().stop();
+
+      String logline = logAppender.getLog(0).toString();
+      assertTrue(logline, logline.matches("^127\\.0\\.0\\.1 - \\[\\d+/\\w+/\\d+:\\d+:\\d+:\\d+ [+-]?\\w+\\] \"PUT /HotRodCache/\\[B0x6B6579 HOTROD/2\\.1\" OK \\d+ \\d+ \\d+$"));
+   }
+}
diff --git a/server/integration/infinispan/src/main/resources/subsystem-templates/infinispan-logging.xml b/server/integration/infinispan/src/main/resources/subsystem-templates/infinispan-logging.xml
@@ -19,7 +19,7 @@
        </periodic-rotating-file-handler>
        <size-rotating-file-handler name="HR-ACCESS-FILE" autoflush="true">
            <formatter>
-               <pattern-formatter pattern="(%t) %s%e%n"/>
+               <named-formatter name="ACCESS-LOG"/>
            </formatter>
            <file relative-to="jboss.server.log.dir" path="hotrod-access.log"/>
            <append value="@@append@@"/>
@@ -28,7 +28,7 @@
        </size-rotating-file-handler>
        <size-rotating-file-handler name="REST-ACCESS-FILE" autoflush="true">
            <formatter>
-               <pattern-formatter pattern="(%t) %s%e%n"/>
+               <named-formatter name="ACCESS-LOG"/>
            </formatter>
            <file relative-to="jboss.server.log.dir" path="rest-access.log"/>
            <append value="@@append@@"/>
@@ -37,14 +37,14 @@
        </size-rotating-file-handler>
 
        <?LOGGERS?>
-       <logger category="org.infinispan.server.hotrod.logging.HotRodAccessLoggingHandler">
+       <logger category="org.infinispan.HOTROD_ACCESS_LOG" use-parent-handlers="false">
            <!-- Set to TRACE to enable access logging for hot rod or use DMR -->
            <level name="INFO"/>
            <handlers>
                <handler name="HR-ACCESS-FILE"/>
            </handlers>
        </logger>
-       <logger category="org.infinispan.rest.logging.RestAccessLoggingHandler">
+       <logger category="org.infinispan.REST_ACCESS_LOG" use-parent-handlers="false">
            <!-- Set to TRACE to enable access logging for rest or use DMR -->
            <level name="INFO"/>
            <handlers>
@@ -64,6 +64,9 @@
        <formatter name="COLOR-PATTERN">
            <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>
        </formatter>
+       <formatter name="ACCESS-LOG">
+           <pattern-formatter pattern="%X{address} %X{user} [%d{dd/MMM/yyyy:HH:mm:ss z}] &quot;%X{method} %m %X{protocol}&quot; %X{status} %X{requestSize} %X{responseSize} %X{duration}%n"/>
+       </formatter>
    </subsystem>
    <supplement name="default">
       <replacement placeholder="@@append@@" attributeValue="true"/>